Changing PASOE agent logging dynamically - Forum - OpenEdge Development - Progress Community

Changing PASOE agent logging dynamically

 Forum

Changing PASOE agent logging dynamically

This question is answered

We use the .Net open client, and any time an S.E.H. error is thrown in ABL, we still need to trap it and convert it to the legacy error format (ie.  RETURN ERROR ch-error).    This was true in classic appserver and it still remains true in PASOE.

Unfortunately there are times when an SEH error is not caught, and bypasses our conversion efforts .  The user gets a generic failure message (Runtime4GLErrorException) in the .net open client, and a message is shown in the logs like so:

[18/11/28] P-000768 T-004092 1 AS-33 -- Cannot throw or return error/stop object to remote client because object is not serializable or client does not support it. (14438)

There is nothing more in the logs to say what the error is, or where it came from.  Therefore, unless the end-user decides to report the failure, this mystery message will never be resolved and will continue to appear in the logs forever.

I'm aware that increasing the logging level and adding 4GLTrace to the log entry types will get to the bottom of the problem.  The issues with this is that, (1) logging needs to be turned on for a very long time to diagnose an infrequent error, and will generate tons of logging in the meantime.  This could be worse than living with the mystery message. And (2) I haven't found a way yet to cause PASOE to dynamically adjust its logging, based on changes in openedge.properties config values.  Even if the agent process for an application is stopped individually and a new one is restarted, it doesn't seem to adjust the logs as requested.  The only solution is to restart the entire instance.  This is disruptive to openclient sessions (end users) with long-lived sessions because it will generate error(s) when the PASOE instance is restarted.

Does anyone have any ideas how, in PASOE, to turn on agent logging dynamically until an error message can be captured, then turn it off again?  These are the logging config values I'd like to be able to manipulate: agentLoggingLevel , agentLogEntryTypes.  I'm quite sure that agents won't pick up my changes to openedge.properties (even new ones that are added on the fly) until the entire PASOE/tomcat instance is restarted.  I believe there may be a way to accomplish this type of thing with system-wide custom-code by adjusting LOG-MANAGER properties myself but I'm hoping this won't be necessary if there is something already built into PASOE that I've overlooked.

Also, is there any log entry type that I may have overlooked that is specifically for S.E.H. error handling.  Ideally I'd be able to turn on logging for all errors thrown ("first-chance" errors) and that would reduce the amount of information sent to the agent logs (as compared to 4GLTrace).

Any help would be appreciated.  I found some links to some very helpful information about logging and PASOE troubleshooting.  But they don't give me a way to adjust logging for an ABL application on the fly without restarting the entire instance.

http://pugchallenge.org/downloads2017/2017NAPUGLogFilesA.pptx 
https://knowledgebase.progress.com/servlet/fileField?id=0BEa0000000TisZ

Thanks in advance, David

Verified Answer
  • Oh.  So you are not talking about what goes into the AppServer log.  You are talking about what gets sent back to the Open Client code.  In that I totally agree with you.  Or I should say WE totally agree with you.  In version 12, we have already fixed this, but so far only for Java Open clients.  i.e,. Error objects can now be serialized back to the client and you will get the error message and error number on the client side. So you would leave in your BLOCK-LEVEL ON ERROR UNDO, THROW directive and would not need your special CATCH block logic anymore.  

    Unfortunately, we have not done it yet for .NET Open clients, but it is on the roadmap.  You can press product management to make this a higher priority.

    And until that happens, at least you should avoid getting error 14438 by removing the BLOCK-LEVEL directive from your top-level server procedures.  Then you will at least see the error message in the AppServer log file even if it doesn't make it back to the client.

  • An update on this.... Irfan claims that in production on 11.7.4 I should be able to change the logging level on the fly.  

    This should allow me to turn up logging to 4 (extended) for long enough to capture the source of a problem and then turn it off again.

    The key is a property, "allowRuntimeUpdates", in PASOE.  As important as this sounds, I am not getting a lot of hits for that property in my google searches.  I'm really hoping it works as described!  I may have to stop pre-existing agent processes for the change to take effect, but even that would be a fairly reasonable compromise.

  • An update on this ... Irfan thinks that logging levels might be able to change on the fly via a PASOE property, allowRuntimeUpdates, which is in OE 11.7.4

All Replies
  • Rather than modify messages and do memory dumps, I would suggest that we just do what you've been alluding to all along - write the original message to the log file (for an AppServer) that caused the 14438 (along with the 14438).  You can log a bug for this.

    And in general, if this comes from a thrown error object, the stack trace from the object should be output if -debugalert is on.  This latter behavior SHOULD already be there, as that is what happens in the GUI version (i.e., the dialog from the Help button of the error alert box).  If not, that is a bug.

    And yes, if your CATCH blocks are not for Progress.Lang.Error, they should be.  Not sure why they wouldn't be already.

  • >> You can log a bug for this.

    I did report this to Progress tech support.

    The support case essentially end with a KB article that implies things are working as designed, see knowledgebase.progress.com/.../Tracking-down-the-root-cause-of-error-14438 ... The recommended method of troubleshooting this error message is to turn on "4GLTrace" log entry type.

    >>  If your CATCH blocks are not for Progress.Lang.Error, they should be.  Not sure why they wouldn't be already.

    Typically a programmer should only catch errors that they know how to handle.  Outside of those specific types of errors, we rely on the execution context (ie. the runtime/framework) to do something intelligent and well-defined with the remaining errors that aren't caught.  Typically the unhandled errors should be printed somewhere for post-mortem analysis, and then the execution context should be stopped and abandoned (ie. in the case of PASOE, the ABL session should probably be recycled).

    CATCH blocks are designed to handle errors of a specific type.  The error type is used as a filter to the CATCH block.  It is true that, in addition to handling well-understood application errors, I could also choose to write a CATCH block for "Progress.Lang.Error", but that seems like a very last-resort.  And it isn't likely that I'll add any value by handling every unforeseeable and unexpected error in my custom code. IE Anything I might do in my custom code is the exact same thing that I would otherwise have expected the runtime/framework to do for me in the first place!  (But of course, PASOE is not currently helping us very much with our unexpected errors).

    Note that the AppError class is documented to be the "ultimate super class of all application errors".  Our custom application errors are derived from it.   By catching all AppError classes (and any derived classes), we are taking care of our own responsibilities.  Any error types outside of this are "above our pay grade" so to speak, and we would expect the runtime/framework to pick up the ball and perform some behavior that is intelligent and well-defined.

  • Any error can be "handled" by simply displaying the error message.  So there is nothing harmful about CATCHing errors that you have no further handling to do other than that.  And yes, if you don't CATCH it, that is what will happen anyway (i.e., the message gets displayed).  But this whole discussion started by the fact that since you are using Open Client and you cannot throw an error back to the .NET client, you need to make sure that all errors are CAUGHT at the top level so you can do your RETURN ERROR logic.  You can never guarantee that a system error will not happen.  Unexpected things DO happen.  So that is why you should be catching Progress.Lang.Error, at least in the top level procedures on the server.

    And without that, the runtime/framework is "picking up the ball" and behaving exactly as documented.  Though I think we already both agree that the AVM should also log the original error message when you get the 14438 message.  But to avoid that message altogether, you should just be catching Progress.Lang.Error objects.

  • On a practical level I agree with you (when using the CLR bridge, for example) .  Especially since the "Progress.Lang.Error" appears to be the go-to exception that is raised for a variety of unrelated reasons.  I will probably wrap CATCH-Progress.Lang.Error around any specific blocks of code that use the CLR bridge. (But I still wouldn't necessarily do this in every single entry-level procedure).

    On a theoretical level I strongly disagree with writing CATCH handlers for Progress.Lang.Error.  Outside of our own AppError-derived errors, our custom programming doesn't necessarily have to be concerned with "system" errors that may be thrown.  (Eg. out-of-memory exceptions, disk full exceptions, network disconnections, database unavailable exceptions, etc.) I've always heard that you should *only* catch exceptions that you know how to handle with your own custom code.

    Those types of "system" or "runtime" errors are interesting, but only insofar as I want their details for post-mortem analysis.  There is very little that an ABL programmer can do to mitigate the problem if the OS itself (or the runtime) has decided to turn against you.  

    And yes, in theory it can be harmful to CATCH errors and handle them in a poor way.  For example, if you are already out of disk space and your catch block is written to write a lot of additional information to the disk, then that error handling can be counter-productive and it might even obscure the original error. Similarly if the network fails and your error handling involves trying to use the network, then that is counter-productive for the same reasons.    These are fairly extreme examples, because we are talking about fairly unexpected errors.  

  • Thanks for the tip about -debugalert.  That will save me tons of time when working with our PASOE (both in dev and production).  I wish I had known about it sooner.

    I did already know about -errorstack, but whenever I needed stack information it was unavailable and I was having to do programming to gather it after the fact.  In other words, my work involved some retroactive & manual programming effort to extract the stack information.  This is challenging if errors are only occurring in production.  Also it was a catch-22 because without having the stack information in the first place, I don't know where to put my manual code that extracts stack information.

    Using -debugalert with -errorstack is going to be a life-saver, provided it's not too noisy.  At first glance, it doesn't print anything to the agent log for run-of-the-mill application errors (ie. when returning regular errors via "RETURN ERROR").  That is a good thing because it means that the logs will only show unexpected/unhandled errors that a programmer hasn't accounted for.

    Here are the details about -debugalert if anyone is interested in using them for PASOE:

    https://documentation.progress.com/output/ua/OpenEdge_latest/index.html#page/dpspr%2Fdebug-alert-(-debugalert).html%23

    ...If the error was generated by throwing an error object from the ABL code and the Error Stack (-errorstack) startup parameter is used, or the ERROR-STACK-TRACE attribute on the SESSION system handle is set to true, then the stack trace also includes the contents of the CallStack property for the unhandled error. 
    

    By comparison .Net, has a ToString() method which will show both the message and the stack trace by default (unless people override it and do something unfortunate that obscures that infromation).  I wish ABL had a well-defined "ToString()" operation that would just puke out everything you need to know about an error and its source.  As things work today, we need to do quite a lot of custom programming to get the same level of information that .Net gives in ToString().  To make things even more interesting,  some ABL error types (like Progress.Lang.AppError) put the error in weird places (ReturnValue) instead of the standard places defined by the generic interface, Progress.Lang.Error.    I would always expect meaningful information from the Progress.Lang.Error (via GetMessage/NumMessages) but sometimes these return nothing at all.

  • Regarding some errors, like AppError, putting the error in weird places: No, we put the string you pass into the appropriate place based on the API method you use.  NEW AppError(<string>) is documented to set the ReturnValue property, not the error message.  NEW AppError(<string>, <number>) will set an error message and error number.  You just have to call the one you want!

    However we do acknowledge that this interface is not intuitive and so many people make the mistake of setting the ReturnValue by mistake when they meant to set an error string.  So we do apologize for that!

  • My recollection is that, where AppError's are concerned, the most natural place to put an error is in the ReturnValue.  I think that THROW'ing an AppError with a ReturnValue is equivalent to using the legacy statement : "RETURN ERROR CH-error" (*** docs below ***).   This is also the way in which our remote openclients have always received an error message which had been raised within appserver.

    *** From docs:  When the AVM encounters the RETURN ERROR statement, it implicitly throws a Progress.Lang.AppError error object and places any error string in the object's ReturnValue property.

    Given how natural it is to put something in the AppError ReturnValue, it is odd that the generic "Progress.Lang.Error" interface seems to have no ability to retrieve the "ReturnValue" error message from one of these AppErrors.  It would be nice if there was a ToString() abstraction that would get the error details regardless of whether they were stored in ReturnValue or in GetMessage/NumMessages.  (Maybe it should give the stack information too, while we're at it).   EG. Below is a block of code which proves that no meaningful message can be extracted from an AppError via the "Progress.Lang.Error" interface:

    BLOCK-LEVEL ON ERROR UNDO, THROW.
    DEFINE VARIABLE p_Error AS CHARACTER NO-UNDO INIT "Unexpected". 
    
    /* ************************************************************************ */
    /* Do the work, and return failures in p_Error.                             */
    /* ************************************************************************ */
    DO ON ERROR UNDO, THROW:
       
       RUN MyLogic/ThrowAndCatch/ThrowError.p. 
     
       CATCH v_ErrorInterface AS Progress.Lang.Error :
           
           
          /* Build message from Progress.Lang.Error      */ 
          DEFINE VARIABLE v_LoopMessages AS INTEGER INITIAL 1 NO-UNDO.
          DEFINE VARIABLE v_ErrorMessages AS CHARACTER INITIAL "" NO-UNDO.
          DO v_LoopMessages = 1 TO v_ErrorInterface:NumMessages:
             
             /* Concatenate them all together */
             v_ErrorMessages = v_ErrorMessages + v_ErrorInterface:GetMessage(v_LoopMessages) + " ".
          END.
           
          p_Error =   "An error was encountered in {&FILE-NAME}. " +
                      "It has " + STRING(v_ErrorInterface:NumMessages > 0, "message: /no message.") + v_ErrorMessages.
             
          /* Done */
          RETURN.         
             
       END CATCH.
       
    END. /* DO */

    The code in my MyLogic/ThrowAndCatch/ThrowError.p can be RETURN ERROR "RETURNED ERROR". or it can be UNDO, THROW NEW Progress.Lang.AppError("THROWN ERROR").  In both cases, an AppError is raised, and in neither case is the related message going to be accessible via the generic Progress.Lang.Error interface.

    One thing that is really quite mysterious to me is why the PASOE agent log knows that -debugalert should be used to print the details about certain errors and not others. Does it filter out ALL error classes that are AppError (or derived from AppError) ?  Or perhaps it maybe it is able to distinguish between when errors are escaping via RETURN ERROR, rather than UNDO, THROW ?  I will try to hunt for a KB.  It seems odd that PASOE makes a clear distinction between two types of errors - ones that should or should not be printed to the agent log.  However from within ABL itself, there is no distinction between the errors (unless it is somehow based on the class type of the error).

  • Yes indeed, putting the sting into the Return value was done to be equivalent with doing RETURN ERROR string.  And that is “natural” when returning an error to an open client that does not yet have the capacity to deal with anything else.  But in a more modern application, the “natural” thing to do is to set the string as an error message.

    It is not odd at all that the Progress.Lang.Error interface does not give you the ability to retrieve the Return Value.  Progress.Lang.Error Is an interface that is shared by all the error objects, and most of them, all but AppError, do not have a Return Value.  Therefore the interface doesn’t have it.  And if a P.L.Error is caught you can get the Return Value by checking if the type of the instance is an AppError.  If it is, you can cast it to an AppError and access the ReturnValue property.  That is the way OO works.

    However, I do agree that it would be good if ToString() gave you all the error messages as a concatenation string, and for an AppError instance, the ReturnValue would be included as well.  That way, all you need is ToString, and regardless of what type you’ve caught, it will give you what you want.  

    Regarding PASOE giving different information for different error types, I was not aware of that.  I suspect it is the difference between RETURN ERROR vs throwing an error object.  But in general, the error handling model was designed to interoperate between the older and newer models in one coherent, integrated fashion.  Therefore, it is doing this, I would consider it a bug.  

  • >> But in a more modern application, the “natural” thing to do is to set the string as an error message

    I think the constructor of AppError that takes a single character string (and puts it in the ReturnValue) will always remain very popular.  The one that also takes a "MessageNumber" parameter seems way too bureaucratic.  It seems to imply that we need to maintaining a registry of all possible errors before our programs are allowed to raise any errors.  The truth is that programs will always have reasons for failure, whether there is a previously registered "MessageNumber" for it or not.

    Maybe the constructor that takes a single character should also add a default Message/MessageNumber pair internally (with a default MessageNumber of MaxInteger or -1 or something).

    >> I suspect it is the difference between RETURN ERROR vs throwing an error object.

    This is what I was thinking too.  It is a good thing that data doesn't print to the agent log except in very limited circumstances.  The RETURN ERROR statement is how "openclient" applications expect to receive business logic errors, and these would fill up the agent log very, very quickly because they happen as a matter of course.

    Peter Judge mentioned this before, but there needs needs to be some way (a method/trigger/event) for us to perform an ABL action based on errors that are "escaping" from an ABL session in PASOE.  It should be up to us to determine what type of stuff is interesting enough to write to the PASOE agent logs.  (We could be responsible for doing this ourselves via calls to the LOG-MANGER from the escaping-error-action-code.)

    Currently it seems like black magic that PASOE can distinguish between AppErrors that are THROWN out of PASOE instead of sent out via RETURN ERROR.  We've always had to write this type of error handling in all our top-level classic appserver entry programs:

    CATCH v_AppError AS Progress.Lang.AppError:
    
    RETURN ERROR v_AppError:ReturnValue.
    
    END CATCH.

    If you don't have this block, then we see the following unhelpful message in our "classic" agent logs: AS -- Attempt to throw or return an error object to the client (14438).  Having the block above should NOT be necessary considering the fact that a THROWN AppError("MyMessage") is virtually identical to RETURN ERRROR "MyMessage". It seems like black magic that PASOE can make a distinction between the two because, from within ABL itself, there doesn't seem to be a way to determine the difference via S.E.H.

    There is additional information in the KB that confirms a difference (in classic appserver) between when an AppError is raised via "THROW" or "RETURN ERROR". See:

    https://knowledgebase.progress.com/articles/Article/000045832

    Since moving to PASOE I haven't yet reviewed whether there is still a distinction between the two ways to raise AppError.  We still have quite a large amount of code running in both "Classic" and "PASOE" so it may be a while before we can remove all those repetitive CATCH-RETURN-ERROR blocks from all our appserver entry programs.

  • You also have the possibility to create your own error class then inherits from AppError and in the class constructer(s) set both ReturnValue and AddMessage

       CONSTRUCTOR PUBLIC Error (c_ReturnValue AS CHARACTER):
          SUPER(c_ReturnValue).
          THIS-OBJECT:AddMessage(IF c_ReturnValue, 0).
       END CONSTRUCTOR.
    
       CONSTRUCTOR PUBLIC Error (c_Message AS CHARACTER, i_Message AS INTEGER):
          SUPER(c_Message, i_Message).
          THIS-OBJECT:ReturnValue = c_Message.
       END CONSTRUCTOR.
  • An alternative to creating an override is to force the AppError to put the message into the message stack (not the return value). Do this by using the (char, int) constructor.

    def var whoopsie as Progress.Lang.AppError.
    
    whoopsie = new AppError('bah humbug').
    message
        whoopsie:ReturnValue skip    // bah humbug
        whoopsie:GetMessage(1)       // <empty>
        view-as alert-box error.
    
    
    whoopsie = new AppError('bah humbug', 0). // ? also works
    message
        whoopsie:ReturnValue skip    // <empty>
        whoopsie:GetMessage(1)       // bah humbug
        view-as alert-box error.
    
  • An update on this.... Irfan claims that in production on 11.7.4 I should be able to change the logging level on the fly.  

    This should allow me to turn up logging to 4 (extended) for long enough to capture the source of a problem and then turn it off again.

    The key is a property, "allowRuntimeUpdates", in PASOE.  As important as this sounds, I am not getting a lot of hits for that property in my google searches.  I'm really hoping it works as described!  I may have to stop pre-existing agent processes for the change to take effect, but even that would be a fairly reasonable compromise.

  • An update on this ... Irfan thinks that logging levels might be able to change on the fly via a PASOE property, allowRuntimeUpdates, which is in OE 11.7.4

  • Yes, I can confirm that logging changes will take effect if you use allowRuntimeUpdates=1  

    The change to the logging can made in OEE, or via openedge.properties.  

    I wish this (allowRuntimeUpdates) was the default behavior.  At least where logging levels are concerned, this is a pretty critical feature!  Now we can easily troubleshoot ABL problems and error messages that only seem to occur in production.