I have a situation where I think PAS is failing and is also failing to relay the failure message. I have some code in appserver like so, where I forgot to prefix with the keyword "DATASET" before calling the WRITE-XML on the dataset handle.
DS_Shift:WRITE-XML("FILE", "shift.xml", TRUE).
If I simply check syntax on this in PDSE, I get "** Unknown Field or Variable name - DS_Shift. (201)".
But things are more confusing in the openclient exception via APSV, as well as the logs (4GLTrace level 4) in PAS. None of the available messages are easily interpreted when attempting to execute the program. For most types of errors, I see the compiler message in both my openclient exception and in the logs. But what bothered me about this particular case is that I think PAS is unable to generate a meaningful error (or at least not one that means anything to me at this stage). I suspect that the problem encountered while performing a runtime compilation is bad enough that PAS not only fails to compile, but also fails to successfully relay the error that is being returned during the compilation.
So here is the message that is received from the APSV client (.net):
Progress.Open4GL.Exceptions.RunTime4GLErrorException occurred HResult=0x80131500 Message=ERROR condition: network exception occurred processing request : com.progress.appserv.broker.exception.BrokerException$NetworkException: Agent : NetworkError[java.net.SocketException: Socket closed : Error reading message for (4DDC53A6124F97155851EDBD8B4B33D3B9CB1827B8BA.oepas_8815) = Socket closed]:Agent (7211) Source=Progress.o4glrt StackTrace: at Progress.Open4GL.Proxy.Procedure.runProcedure(String requestID, String procName, ParameterSet params_Renamed, MetaSchema schema) at Progress.Open4GL.Proxy.Procedure.runProcedure(String procName, ParameterSet params_Renamed, MetaSchema schema) at MyCoolProxies.Proxy.Shift.GetShiftData(DS_ShiftDataSet& DS_Shift)
And here is the output from two different logs related to this ABL app/webapp:
[17/12/05@12:36:42.873-0500] P-017580 T-024048 4 AS-Admin AS Server Message state = MSGSTATE_IDLE [17/12/05@12:36:42.878-0500] P-017580 T-022844 1 AS-Aux-5 -- Log entry types activated: ASPlumbing,DB.Connects,4GLTrace,4GLTrans [17/12/05@12:36:42.878-0500] P-017580 T-022844 2 AS-Aux-5 AS Starting MSAS Session for abl_dev_statefree_dkb. [17/12/05@12:36:42.878-0500] P-017580 T-022844 2 AS-Aux-5 AS MSAS Session Startup. (5473) [17/12/05@12:36:42.879-0500] P-017580 T-022844 4 AS-4 AS Server Message state = MSGSTATE_INITRQ [17/12/05@12:36:42.879-0500] P-017580 T-022844 3 AS-4 AS requestID= <REQ|08fgymL3Ok2VOj9p8rlHpw-00000001> [17/12/05@12:36:42.879-0500] P-017580 T-022844 4 AS-4 AS -- TRACE: Set open 4GL server state to 1. (8400) [17/12/05@12:36:42.879-0500] P-017580 T-022844 4 AS-4 AS -- TRACE: Open4GLWriteLast 60. (8401) [17/12/05@12:36:42.879-0500] P-017580 T-022844 4 AS-4 AS -- TRACE: Open4GLWrite 60. (8402) [17/12/05@12:36:42.879-0500] P-017580 T-022844 4 AS-4 AS -- TRACE: cso4GL: Before loadProc() (8458) [17/12/05@12:36:42.879-0500] P-017580 T-022844 3 AS-4 AS -- TRACE: PERSISTENT Procedure 'app/Production/AppServer/Shift.p' START (Proxy 1). [17/12/05@12:36:42.922-0500] P-017580 T-022844 4 AS-4 AS -- TRACE: cso4GL: After successful loadProc() (8458) [17/12/05@12:36:42.922-0500] P-017580 T-022844 4 AS-4 AS -- TRACE: Set open 4GL server state to 2. (8400) [17/12/05@12:36:42.922-0500] P-017580 T-022844 4 AS-4 AS -- TRACE: cso4GL: In execProc() - before execution. (8458) [17/12/05@12:36:42.922-0500] P-017580 T-022844 3 AS-4 4GLTRACE Return from Main Block [app/Production/AppServer/Shift.p] [17/12/05@12:36:42.922-0500] P-017580 T-022844 3 AS-4 AS -- TRACE: PERSISTENT Procedure (Proxy 1) END SUCCESS. [17/12/05@12:36:42.922-0500] P-017580 T-022844 4 AS-4 AS -- TRACE: cso4GL: In execProc() - successful execution. (8458) [17/12/05@12:36:42.922-0500] P-017580 T-022844 4 AS-4 AS -- TRACE: cso4GL: In execCall() - execProc() success. (8458) [17/12/05@12:36:42.922-0500] P-017580 T-022844 4 AS-4 AS -- TRACE: Set open 4GL server state to 3. (8400) [17/12/05@12:36:42.922-0500] P-017580 T-022844 4 AS-4 AS Server Message state = MSGSTATE_SENDRESP [17/12/05@12:36:42.922-0500] P-017580 T-022844 4 AS-4 AS -- TRACE: Set open 4GL server state to 1. (8400) [17/12/05@12:36:42.922-0500] P-017580 T-022844 4 AS-4 AS -- TRACE: open4GLRead 31. (8403) [17/12/05@12:36:42.922-0500] P-017580 T-022844 4 AS-4 AS Server Message state = MSGSTATE_FINISHRQ [17/12/05@12:36:42.922-0500] P-017580 T-022844 4 AS-4 AS Server Message state = MSGSTATE_IDLE [17/12/05@12:36:42.971-0500] P-017580 T-022844 4 AS-4 AS Server Message state = MSGSTATE_INITRQ [17/12/05@12:36:42.971-0500] P-017580 T-022844 3 AS-4 AS requestID= <REQ|08fgymL3Ok2VOj9p8rlHpw-00000002> [17/12/05@12:36:42.971-0500] P-017580 T-022844 4 AS-4 AS -- TRACE: Open4GLWriteLast 261. (8401) [17/12/05@12:36:42.971-0500] P-017580 T-022844 4 AS-4 AS -- TRACE: Open4GLWrite 261. (8402) [17/12/05@12:36:42.971-0500] P-017580 T-022844 4 AS-4 AS -- TRACE: cso4GL: Before loadProc() (8458) [17/12/05@12:36:42.971-0500] P-017580 T-022844 3 AS-4 AS -- TRACE: Internal Procedure 'GetShiftData' (in 'app/Production/AppServer/Shift.p') START (Proxy 1).
<<< ??? (error is in a class file that is called from Shift.p) [17/12/05@12:36:42.971-0500] P-017580 T-022844 4 AS-4 AS -- TRACE: cso4GL: After successful loadProc() (8458) [17/12/05@12:36:42.971-0500] P-017580 T-022844 4 AS-4 AS -- TRACE: Set open 4GL server state to 8. (8400) [17/12/05@12:36:42.971-0500] P-017580 T-022844 4 AS-4 AS -- TRACE: Set open 4GL server state to 8. (8400) [17/12/05@12:36:42.971-0500] P-017580 T-022844 4 AS-4 AS -- TRACE: Set open 4GL server state to 2. (8400) [17/12/05@12:36:42.971-0500] P-017580 T-022844 4 AS-4 AS Server Message state = MSGSTATE_SENDRESP [17/12/05@12:36:42.971-0500] P-017580 T-022844 4 AS-4 AS -- TRACE: cso4GL: In execProc() - before execution. (8458) ========= 12:36:45.314/23457 [xXUBwzg6RrejhqchK27x3g-agent-watchdog] WARN c.p.appserv.PoolMgt.AgentWatchdog - AgentWatchdog(xXUBwzg6RrejhqchK27x3g) : agent -927YaQeTdK7r2UAzbwm8A PID= 17580 has terminated. 12:36:45.322/17694 [catalina-exec-4] ERROR com.progress.appserv.Session - LocalSession(AE80A6A5BD2930041E9A2ED814369DFC9BC01E022BB0.oepas_8815) : error occurred while reading a message processAgentRsp() = java.net.SocketException: Socket closed:Socket closed. (18300) 12:36:45.323/16092 [catalina-exec-4] ERROR com.progress.appserv.Agent - releaseABLSession(-927YaQeTdK7r2UAzbwm8A) failed : invalid session count = 0 (18234) 12:36:45.325/16094 [catalina-exec-4] WARN c.p.appserv.PoolMgt.Connection - TcpAgentConnectionPool(msapYxPuSS2Yr4zVsKT4Fg) : removeAgentConnection() failed to remove connection : size= 0 max= 1 12:36:45.325/17697 [catalina-exec-4] ERROR com.progress.appserv.Session - LocalSession(AE80A6A5BD2930041E9A2ED814369DFC9BC01E022BB0.oepas_8815) : an error occurred while reading response message = java.net.SocketException: Socket closed:Socket closed. (18296)
So it seems to me that there are some corner cases where the error message returned from the ABL compilation process is causing some kind of an internal error in PAS so that it won't be relayed to the openclient, nor appear in the logs.
Note that this is not the general case . In the general case if I put bad code in a program (ie, add a line that says "asdfasdf" then the logs are more intelligible.
[17/12/05@12:58:58.971-0500] P-017256 T-000900 4 AS-4 AS -- TRACE: Set open 4GL server state to 1. (8400) [17/12/05@12:58:58.971-0500] P-017256 T-000900 4 AS-4 AS -- TRACE: Open4GLWriteLast 60. (8401) [17/12/05@12:58:58.971-0500] P-017256 T-000900 4 AS-4 AS -- TRACE: Open4GLWrite 60. (8402) [17/12/05@12:58:58.971-0500] P-017256 T-000900 4 AS-4 AS -- TRACE: cso4GL: Before loadProc() (8458) [17/12/05@12:58:58.971-0500] P-017256 T-000900 3 AS-4 AS -- TRACE: PERSISTENT Procedure 'app/Production/AppServer/Shift.p' START (Proxy 1). [17/12/05@12:58:59.024-0500] P-017256 T-000900 4 AS-4 AS -- TRACE: cso4GL: loadProc() failed. (8458) [17/12/05@12:58:59.024-0500] P-017256 T-000900 4 AS-4 AS -- TRACE: Set open 4GL server state to 5. (8400) [17/12/05@12:58:59.024-0500] P-017256 T-000900 4 AS-4 AS Server Message state = MSGSTATE_SENDRESP [17/12/05@12:58:59.024-0500] P-017256 T-000900 4 AS-4 AS -- TRACE: Set open 4GL server state to 1. (8400) [17/12/05@12:58:59.024-0500] P-017256 T-000900 1 AS-4 -- ** Unable to understand after -- "asdfasdf". (247) [17/12/05@12:58:59.024-0500] P-017256 T-000900 1 AS-4 -- ** \\grnetappm02\dbeavon\Wrk\OpenEdge\LumberTrack\app\Production\Shift.cls Could not understand line 67. (198) [17/12/05@12:58:59.024-0500] P-017256 T-000900 1 AS-4 -- Missing END METHOD statement. (12968) [17/12/05@12:58:59.024-0500] P-017256 T-000900 1 AS-4 -- ** \\grnetappm02\dbeavon\Wrk\OpenEdge\LumberTrack\app\Production\Shift.cls Could not understand line 71. (196) [17/12/05@12:58:59.024-0500] P-017256 T-000900 1 AS-4 -- Could not find class or interface app.Production.Shift. (12886) [17/12/05@12:58:59.024-0500] P-017256 T-000900 1 AS-4 -- ** \\grnetappm02\dbeavon\Wrk\OpenEdge\LumberTrack\app\Production\AppServer\Shift.p Could not understand line 28. (196) [17/12/05@12:58:59.024-0500] P-017256 T-000900 4 AS-4 AS -- TRACE: open4GLRead 144. (8403) [17/12/05@12:58:59.024-0500] P-017256 T-000900 4 AS-4 AS Server Message state = MSGSTATE_FINISHRQ [17/12/05@12:58:59.024-0500] P-017256 T-000900 4 AS-4 AS Server Message state = MSGSTATE_IDLE
Can someone please comment on my theory about two possible types of compile failures (only one of which generates helpful output). At this point I am thinking I am running into a failure on top of a failure, and its causing the original root cause of the failures to be obscured.