FWD » Core Development » Base Language

Log Manager Usage

The base implementation is already handled at conversion and it is stubbed out in the runtime. The biggest effort will be writing testcases identify the runtime locations for instrumentation. The used LOG-ENTRY-TYPES does not look very hard to implement.

LOG-MANAGER system handle

Attributes

LOGFILE-NAME
LOGGING-LEVEL
LOG-ENTRY-TYPES
LOG-THRESHOLD
ENTRY-TYPES-LIST
NUM-LOG-FILES
QUERY:BASIC-LOGGING

Methods

WRITE-MESSAGE
CLEAR-LOG
CLOSE-LOG

Some details about the customer application usage:

• LOGGING-LEVEL is set to 2, 3
  • 0 ("none"), means no logging
  • 1 ("errors"), this would log only 4GL error messages and ignores the LOG-ENTRY-TYPES setting
  • 2 ("basic"), includes "errors" plus categories defined in LOG-ENTRY-TYPES
• LOG-ENTRY-TYPES is set to one of the following
  • "QryInfo:2,4GLMessages" (this is used in non-appserver mode)
  • "QryInfo:2,ASDefault" (used in appserver mode)
  • "4GLTrace"
  • "4GLMessages"
  • At least in 1 location it is set to an arbitrary value.
  • 4GLTrace logs on execution of internal procedures, functions, events etc...
  • 4GLTrans logs on transactions and sub-transactions
  • QryInfo logs queries (open query and for each)
  • ASPlumbing logs unspecified appserver events
  • DB.Connects logs database connects/disconnects
  • 4GLMessages logs MESSAGE statement output (the same way that appserver and batch does this without the LOG-MANAGER)
  • session:debug-alert IS explicitly set so 4GLMessages does also include stack traces (yikes!)
  • ASDefault is the same as ASPlumbing + DB.Connects
  • WSADefault

• Methods:
• clear-log() - will generate a file:
  • call method w/o setting a log file
  • call method after setting log file and add content - check sizes before and after
• close-log() - will generate a file:
  • call method w/o setting a log file
  • call method after setting a log file
  • call method write-message after close log
• write-message() - will generate a file:
  • call method w/o setting a log file
  • call method after set a log file compare sizes before and after
  • test default and explicit use of subsys expression parameter

• Attributes:
• entry-types-list - no file generated:
  • get list from log-manager
  • test if read-only
• logfile-name - generated file is deleted after test by test procedure:
  • use relative path:
    • check default value
    • create file, add info apply attribute -> check sizes
    • delete file, apply attribute check file then delete again
  • use absolute path:
    • check default value
    • create file, add info apply attribute -> check sizes
    • delete file, apply attribute check file then delete again
  • use wrong path syntax
  • call attribute after close-log() method
• logging-level - generated file is deleted after test by test procedure:
  • get default value
  • apply attribute w/o set log file
  • set logging level out of range
  • delete file used for tests
• log-threshold - no file generated
  • get default value
  • test if read only
• num-log-files - no file generated
  • get default value
  • test if read only
• log-entry-types - default and errors - will generate a file
  • apply attribute w/o set a log file
  • set a log file and apply with a value who is not in the list
• log-entry-types - 4glmessages - will generate a file
  • set logging level to 0 and 1 for this attribute
    • set session:debug-alert to true and false
  • set logging level to 2, 3 and 4 for this attribute
    • set session:debug-alert to true and false
    • apply message with view-as alert-box options
• log-entry-types - 4gltrace_events - will generate a file
  • set logging level from 2 to 4 and
    • call event on run with asynchronous
    • subscribe to an event - procedural way
    • publish event - procedural way
    • subscribe to an event - oo way
    • publish event - oo way
• log-entry-types - 4gltrace - will generate a file
  • set logging level from 2 to 4 and
    • call internal procedure
    • invoke internal function
    • call procedure from external procedure
    • call function from external procedure
    • call trigger
    • call static method from class
    • use method from class
    • instantiate a class
    • use class property
    • call procedure from appserver classic and asynchronous
    • delete object
• log-entry-types - 4gltrans - will generate a file
  • set logging level from 2 to 4 and
    • perform transaction in database
    • perform sub-transaction in database
    • return from sub-transaction with undo
• log-entry-types - db_connects - will generate a file
  • set logging level from 2 to 4 and
    • perform connects and disconnects from database
• log-entry-types - dynobjects - will generate a file
  • set logging level from 2 to 4 and
    • instantiate a lang object
    • run persistent procedure
    • perform an async request
    • memptr - set size
    • create dynamic handles for all options
• log-entry-types - fileid - will generate a file
  • set logging level from 2 to 4 and
    • open and close a file
• log-entry-types - qryinfo - will generate several files
  • set logging level from 2 to 4 and
    • client sort - find with where for non pk field
    • filter - for each/first/last
    • lock - find with no-lock/exclusive-lock/share/lock
    • multiple-index - where for pk and other filed
    • open-query - open dynamically for static and dynamic defined query
    • preselect - use this option on do and repeat
    • scrolling - use for open query
    • whole-index - apply where for non index fields

Consider the following log output examples.

[19/07/10@11:24:38.981+0300] P-004424 T-002588 1 4GL -- No entry types are activated
[19/07/10@11:24:38.981+0300] P-004424 T-002588 1 4GL -- No entry types are activated
[19/07/10@11:24:38.981+0300] P-004424 T-002588 1 4GL -- Log entry types activated: 4glmessages:2
[19/07/10@11:24:38.982+0300] P-004424 T-002588 2 4GL 4GLMESSAGE     logging-level:2 - debug-alert=true
[19/07/10@11:24:38.982+0300] P-004424 T-002588 2 4GL 4GLMESSAGE     ** ABL Debug-Alert Stack Trace **
[19/07/10@11:24:38.982+0300] P-004424 T-002588 2 4GL 4GLMESSAGE     --> C:\Progress\workspace\testcases\log_manager\attributes\log_entry_types_4glmessages.p at line 177  (C:\Progress\workspace\testcases\log_manager\attributes\log_entry_types_4glmessages.r)

[19/07/11@14:22:04.773+0300] P-011956 T-007000 1 4GL -- No entry types are activated
[19/07/11@14:22:04.773+0300] P-011956 T-007000 1 4GL -- Log entry types activated: 4gltrans:2
[19/07/11@14:22:04.773+0300] P-011956 T-007000 3 4GL 4GLTRANS       BEGIN TRANS 250 [log_manager/common/transactions.p @ 3]
[19/07/11@14:22:04.774+0300] P-011956 T-007000 3 4GL 4GLTRANS       END TRANS 250 [log_manager/common/transactions.p @ 16]
[19/07/11@14:22:04.774+0300] P-011956 T-007000 1 4GL -- Log entry types activated: 4gltrans:3
[19/07/11@14:22:04.774+0300] P-011956 T-007000 3 4GL 4GLTRANS       BEGIN TRANS 260 [log_manager/common/transactions.p @ 3]
[19/07/11@14:22:04.774+0300] P-011956 T-007000 3 4GL 4GLTRANS       BEGIN SUB-TRANS 261 [log_manager/common/transactions.p @ 6]
[19/07/11@14:22:04.774+0300] P-011956 T-007000 3 4GL 4GLTRANS       BEGIN SUB-TRANS 262 [log_manager/common/transactions.p @ 7]
[19/07/11@14:22:04.774+0300] P-011956 T-007000 3 4GL 4GLTRANS       BEGIN SUB-TRANS 263 [log_manager/common/transactions.p @ 9]
[19/07/11@14:22:04.774+0300] P-011956 T-007000 3 4GL 4GLTRANS       UNDO SUB-TRANS 263 [log_manager/common/transactions.p @ 13]
[19/07/11@14:22:04.774+0300] P-011956 T-007000 3 4GL 4GLTRANS       END SUB-TRANS 262 [log_manager/common/transactions.p @ 14]
[19/07/11@14:22:04.774+0300] P-011956 T-007000 3 4GL 4GLTRANS       END SUB-TRANS 261 [log_manager/common/transactions.p @ 15]
[19/07/11@14:22:04.774+0300] P-011956 T-007000 3 4GL 4GLTRANS       END TRANS 260 [log_manager/common/transactions.p @ 16]

[19/07/15@13:41:17.751+0300] P-013120 T-006964 1 4GL -- Logging level set to = 2
[19/07/15@13:41:17.751+0300] P-013120 T-006964 1 4GL -- No entry types are activated
[19/07/15@13:41:17.751+0300] P-013120 T-006964 1 4GL ----------     Log file closed at user's request
[19/07/15@13:41:17.887+0300] P-013120 T-006964 1 4GL -- Logging level set to = 2
[19/07/15@13:41:17.887+0300] P-013120 T-006964 1 4GL -- No entry types are activated
[19/07/15@13:41:17.887+0300] P-013120 T-006964 1 4GL -- Log entry types activated: qryinfo:2
[19/07/15@13:41:17.895+0300] P-013120 T-006964 2 4GL QRYINFO        Query Info Logging turned on for query stDefQuery handle 0 QueryId 1570746230280
[19/07/15@13:41:17.896+0300] P-013120 T-006964 2 4GL QRYINFO        Query Info Logging turned on for query  handle 1013 QueryId 1570746519680
[19/07/15@13:41:17.896+0300] P-013120 T-006964 1 4GL APPL           open statically - start
[19/07/15@13:41:17.896+0300] P-013120 T-006964 2 4GL QRYINFO        Query Plan:  log_manager/common/qryinfo_open_query.p line 22
[19/07/15@13:41:17.896+0300] P-013120 T-006964 2 4GL QRYINFO        QueryId: 1570746230280
[19/07/15@13:41:17.896+0300] P-013120 T-006964 2 4GL QRYINFO        Query Name: stDefQuery
[19/07/15@13:41:17.896+0300] P-013120 T-006964 2 4GL QRYINFO        Query Handle: 0
[19/07/15@13:41:17.896+0300] P-013120 T-006964 2 4GL QRYINFO        Type: Statically Opened Query
[19/07/15@13:41:17.896+0300] P-013120 T-006964 2 4GL QRYINFO        Prepared at Compile time
[19/07/15@13:41:17.896+0300] P-013120 T-006964 2 4GL QRYINFO        Client Sort: N 
[19/07/15@13:41:17.896+0300] P-013120 T-006964 2 4GL QRYINFO        Scrolling: N
[19/07/15@13:41:17.896+0300] P-013120 T-006964 2 4GL QRYINFO        Table: C:\Progress\workspace\testcases\fwd\fwd.customer
[19/07/15@13:41:17.896+0300] P-013120 T-006964 2 4GL QRYINFO          Indexes: pk
[19/07/15@13:41:17.896+0300] P-013120 T-006964 1 4GL APPL           open statically - end
[19/07/15@13:41:17.896+0300] P-013120 T-006964 1 4GL APPL           open dynamic for static query - start
[19/07/15@13:41:17.896+0300] P-013120 T-006964 2 4GL QRYINFO        Query Statistics:  log_manager/common/qryinfo_open_query.p line 32
[19/07/15@13:41:17.896+0300] P-013120 T-006964 2 4GL QRYINFO        QueryId: 1570746230280
[19/07/15@13:41:17.896+0300] P-013120 T-006964 2 4GL QRYINFO        Query Name: stDefQuery
[19/07/15@13:41:17.896+0300] P-013120 T-006964 2 4GL QRYINFO        Query Handle: 1015
[19/07/15@13:41:17.896+0300] P-013120 T-006964 2 4GL QRYINFO        Times opened: 1
[19/07/15@13:41:17.896+0300] P-013120 T-006964 2 4GL QRYINFO        Used REPOSITION: N
[19/07/15@13:41:17.896+0300] P-013120 T-006964 2 4GL QRYINFO        DB Blocks accessed:
[19/07/15@13:41:17.896+0300] P-013120 T-006964 2 4GL QRYINFO         C:\Progress\workspace\testcases\fwd\fwd : 0
[19/07/15@13:41:17.896+0300] P-013120 T-006964 2 4GL QRYINFO        DB Reads:
[19/07/15@13:41:17.896+0300] P-013120 T-006964 2 4GL QRYINFO         Table: C:\Progress\workspace\testcases\fwd\fwd.customer : 0
[19/07/15@13:41:17.896+0300] P-013120 T-006964 2 4GL QRYINFO        C:\Progress\workspace\testcases\fwd\fwd.customer Table:
[19/07/15@13:41:17.896+0300] P-013120 T-006964 2 4GL QRYINFO         4GL Records: 0
[19/07/15@13:41:17.896+0300] P-013120 T-006964 2 4GL QRYINFO         Records from server: 0
[19/07/15@13:41:17.896+0300] P-013120 T-006964 2 4GL QRYINFO          Useful: 0
[19/07/15@13:41:17.896+0300] P-013120 T-006964 2 4GL QRYINFO          Failed: 0
[19/07/15@13:41:17.896+0300] P-013120 T-006964 2 4GL QRYINFO         Select By Client: N
[19/07/15@13:41:17.897+0300] P-013120 T-006964 2 4GL QRYINFO        Query Plan:  log_manager/common/qryinfo_open_query.p line 32
[19/07/15@13:41:17.897+0300] P-013120 T-006964 2 4GL QRYINFO        QueryId: 1570746230280
[19/07/15@13:41:17.897+0300] P-013120 T-006964 2 4GL QRYINFO        Query Name: stDefQuery
[19/07/15@13:41:17.897+0300] P-013120 T-006964 2 4GL QRYINFO        Query Handle: 1015
[19/07/15@13:41:17.897+0300] P-013120 T-006964 2 4GL QRYINFO        Type: Dynamically Opened Query
[19/07/15@13:41:17.897+0300] P-013120 T-006964 2 4GL QRYINFO        PREPARE-STRING: for each fwd.customer where customerName = "Ion Anton" 
[19/07/15@13:41:17.897+0300] P-013120 T-006964 2 4GL QRYINFO        Prepared at Runtime
[19/07/15@13:41:17.897+0300] P-013120 T-006964 2 4GL QRYINFO        Client Sort: N 
[19/07/15@13:41:17.897+0300] P-013120 T-006964 2 4GL QRYINFO        Scrolling: Y

I have these questions about the content and formatting of the log entries.

• Is P-999999 an operating system pid?
• Is T-999999 an operating system thread id?
• If this was run under PASOE, would we see output (in a single log file) with the same P-999999 but different T-999999 values?
• The logs look like they were captured in Windows, what do those values look like on Linux?
• What is the one digit number that appears before the text 4GL? At first glance I thought it was the logging level associated with the log entry, but in the second example above the logging level is set to 4gltrans:2 but there is output listed as ... 3 4GL ....
• Why is there a difference in the indention level for the actual log messages? Are certain messages always indented the same amount or is there some meaning to the indention levels?

Greg Shah wrote:

I have these questions about the content and formatting of the log entries.

• Is P-999999 an operating system pid?

yes, not relevant in the log file imho but it's there

• Is T-999999 an operating system thread id?

same, completely irrelevant though

• If this was run under PASOE, would we see output (in a single log file) with the same P-999999 but different T-999999 values?

that might, they do say it's a multi-threaded agent but this is probably that is visible in a high load environment not in our development

• The logs look like they were captured in Windows, what do those values look like on Linux?

not very different, the pid is still on six digits while the thread id is using ten... right now we don't have any linux environment setup for FWD

[19/12/04@07:00:36.802+0000] P-000309 T-2426324864 1 4GL -- Logging level set to
 = 2
[19/12/04@07:00:36.802+0000] P-000309 T-2426324864 1 4GL -- Log entry types acti
vated: qryinfo:4
[19/12/04@07:00:36.830+0000] P-000309 T-2426324864 2 4GL QRYINFO    Query Plan: 
 test.p line 1
[19/12/04@07:00:36.830+0000] P-000309 T-2426324864 2 4GL QRYINFO    QueryId: 0x1
57f418
[19/12/04@07:00:36.830+0000] P-000309 T-2426324864 2 4GL QRYINFO    Type: FOR St
atement
[19/12/04@07:00:36.830+0000] P-000309 T-2426324864 2 4GL QRYINFO    Client Sort:
 N 
[19/12/04@07:00:36.830+0000] P-000309 T-2426324864 2 4GL QRYINFO    Scrolling: N
[19/12/04@07:00:36.830+0000] P-000309 T-2426324864 2 4GL QRYINFO    Table: db/sp
orts2000.Customer

• What is the one digit number that appears before the text 4GL? At first glance I thought it was the logging level associated with the log entry, but in the second example above the logging level is set to 4gltrans:2 but there is output listed as ... 3 4GL ....

That is the log level, it does seems to be an error/bug there since according to this KB entry the begin/end transaction entries should be level 2.
https://knowledgebase.progress.com/articles/Article/P96551

• Why is there a difference in the indention level for the actual log messages? Are certain messages always indented the same amount or is there some meaning to the indention levels?

No idea but there seems to be always only one space between the first five entries then the lines with a specific type there is a space followed by the entry type and then a tab (actually 4 spaces) and whatever detail message that follows. For other non type specific lines there seems to be a space followed by at least two dashes, those aren't really important anyway.

As part of this task, we should ensure that the default appserver logging that occurs in the 4GL is fully supported in FWD. This must include suitable control over the log filename and the generation/formatting of the appserver log entries, including timestamps.

I've seen something interesting in a logmanager test:

def var h as handle.
run cc.p on h asynchronous set h (output i as char).

You can inline the var definition, only if the RUN is an async request. I'm changing Marian's tests to explicitly define the var.

OK. Please create a task to record the problem so we don't forget it.

Constantin Asofiei wrote:

I've seen something interesting in a logmanager test:
[...]

You can inline the var definition, only if the RUN is an async request. I'm changing Marian's tests to explicitly define the var.

What test does that exactly Constantin, inline variable definition isn't possible in 4gl... both variables used for `on` and `set` should be defined as handle before. The first one is for the remote server handle where the RPC is made and second is to save a handle to the remote async procedure to use it later. It is not mandatory to save that handle, especially if you event-procedure option is used. Also one can find all pending remote procedures using session system handle and walk the three starting from the first-procedure.

Marian Edu wrote:

What test does that exactly Constantin, inline variable definition isn't possible in 4gl... both variables used for `on` and `set` should be defined as handle before. The first one is for the remote server handle where the RPC is made and second is to save a handle to the remote async procedure to use it later. It is not mandatory to save that handle, especially if you event-procedure option is used. Also one can find all pending remote procedures using session system handle and walk the three starting from the first-procedure.

See log_manager/common/dyn_objects.p and profiler/procedure_class/procedure.p, this statement with charRsp:

run pipe_char.p on appsrv asynchronous set hreq event-procedure "onDone" (input 'test', output charRsp as character).

Constantin Asofiei wrote:

See log_manager/common/dyn_objects.p and profiler/procedure_class/procedure.p, this statement with charRsp:
[...]

Yes, both variables are already defined... appsrv is inside the include file connect.i, that might have been the source for confusion, sorry for that.

Marian Edu wrote:

Constantin Asofiei wrote:

See log_manager/common/dyn_objects.p and profiler/procedure_class/procedure.p, this statement with charRsp:
[...]

Yes, both variables are already defined... appsrv is inside the include file connect.i, that might have been the source for confusion, sorry for that.

See the charRsp parameter - that's the inline definition.

Constantin Asofiei wrote:

See the charRsp parameter - that's the inline definition.

Ah, I see... that is a placeholder, it can be a local variable but for async calls when I see a local variable used as an output parameter I start looking for herrings, chances are the developer doesn't know the actual behaviour :(

For OUTPUT parameters of an asynchronous remote procedure call only, you can specify parameter-name AS primitive-type-name as a prototype. The parameter-name is an arbitrary place-holder name and primitive-type-name must specify the ABL data type of the corresponding OUTPUT parameter in the asynchronous remote procedure. You can also specify OUTPUT parameters for an asynchronous remote procedure using a local field, variable, TABLE temp-table-name, TABLE-HANDLE temp-table-handle, DATASET dataset-name, or DATASET-HANDLE dataset-handle. However, note that the asynchronous remote procedure does not return any values to OUTPUT or INPUT-OUTPUT parameters on the RUN statement. These parameters are place holders only for values returned by the remote procedure to the specified event-internal-procedure.

Please see #4384-396 for some discussion about logging in the built-in OO classes. There will be work there to test and resolve any logging differences.

A note for the implementation: considering that the Java client associated with a Web client runs on the same machine with other users (even the same username), logfile-name or the folder where this is output needs to be unique, and not collide with another user's log file.

The FWD implementation can make sure to add a numeric suffix so that it does not collide (like a log rotation), but the application logic should add at least the application username or otherwise create a folder structure to output these logs.

-clientlog startup parameter is part of this task: https://docs.progress.com/bundle/openedge-abl-troubleshoot-applications-117/page/Specifying-the-log-filename.html

In 6129a/13924 I've added experimental WRITE-MESSAGE and LOGFILE-NAME, to just dump the messages to server's log.

As part of this task we should also support bootstrap configuration overrides that provide an equivalent feature for these 4GL command line options:

• logginglevel
• logfile
• logentrytypes
• logthreshold
• logname
• numlogfiles

Greg Shah wrote:

The base implementation is already handled at conversion and it is stubbed out in the runtime.

Does it mean the logic creating messages for logging is already implemented? Can you point me to what classes to look in for it?

The used LOG-ENTRY-TYPES does not look very hard to implement.

The entry types for the client context are as follows: 4GLMessages, 4GLTrace, 4GLTrans, AiaMgmt, AiaProp, AiaRqst, AiaUbroker, AiaDefault, ASDefault, ASPlumbing, DB.Connects, DS.Cursor, DS.QryInfo, DynObjects.DB, DynObjects.XML, DynObjects.Other, DynObjects.Class, DynObjects.UI, FileID, IgnoredOps, MsgrTrace, NSPlumbing, ProEvents.UI.Char, ProEvents.UI.Command, ProEvents.Other, QryInfo, SAX, Temp-tables, TTStats, UBroker.Basic, UBroker.ClientFSM, UBroker.ServerFSM, UBroker.ClientMsgStream, UBroker.ServerMsgStream, UBroker.ClientMsgQueue, UBroker.ServerMsgQueue, UBroker.ClientMemTrace, UBroker.ServerMemTrace, UBroker.ThreadPool, UBroker.Stats, UBroker.AutoTrim, UBroker.All, WSADefault, DS.Performance

Do we have that separation in the logic handled at conversion?

The base implementation is already handled at conversion and it is stubbed out in the runtime.

Does it mean the logic creating messages for logging is already implemented? Can you point me to what classes to look in for it?

In the testcases project, there is an example of using WRITE-MESSAGE() (log_manager/methods/write_message.p). I assume that is what you are talking about as "creating messages"?

If you convert that program:

java -classpath p2j/build/lib/p2j.jar com.goldencode.p2j.convert.ConversionDriver F2+M0+CB log_manager/methods/write_message.p 2>&1 | tee "cvt_$(date +%Y%m%d_%H%M%M%S).log"

You can then look at the converted code in src/com/goldencode/testcases/log_manager/methods/WriteMessage.java and compare it to the 4GL.

For example, this section of 4GL code:

//set a log file , get size, call method , get size and compare sizes 
log-manager:logfile-name = 'log_manager/files/write_message.log'.

//get initial file size
file-info:file-name = 'log_manager/files/write_message.log'.
initFileSize = file-info:file-size.

//write message with default subsys-expression
logicalRsp = log-manager:write-message ('test message') no-error.

corresponds to this Java code:

         // set a log file , get size, call method , get size and compare sizes 
         LegacyLogOps.logMgr().setLogFileName(new character("log_manager/files/write_message.log"));         

         // get initial file size
         FileSystemOps.initFileInfo(new character("log_manager/files/write_message.log"));
         initFileSize.assign(FileSystemOps.fileInfoGetSize());         

         // write message with default subsys-expression
         silent(() -> logicalRsp.assign(LegacyLogOps.logMgr().writeMessage("test message")));

From there I expect you can find the runtime classes in FWD which are referenced.

The used LOG-ENTRY-TYPES does not look very hard to implement.

The entry types for the client context are as follows: 4GLMessages, 4GLTrace, 4GLTrans, AiaMgmt, AiaProp, AiaRqst, AiaUbroker, AiaDefault, ASDefault, ASPlumbing, DB.Connects, DS.Cursor, DS.QryInfo, DynObjects.DB, DynObjects.XML, DynObjects.Other, DynObjects.Class, DynObjects.UI, FileID, IgnoredOps, MsgrTrace, NSPlumbing, ProEvents.UI.Char, ProEvents.UI.Command, ProEvents.Other, QryInfo, SAX, Temp-tables, TTStats, UBroker.Basic, UBroker.ClientFSM, UBroker.ServerFSM, UBroker.ClientMsgStream, UBroker.ServerMsgStream, UBroker.ClientMsgQueue, UBroker.ServerMsgQueue, UBroker.ClientMemTrace, UBroker.ServerMemTrace, UBroker.ThreadPool, UBroker.Stats, UBroker.AutoTrim, UBroker.All, WSADefault, DS.Performance

In case this was not clear: we only need a subset of these types. We will implement those types which are documented above in #3853-1.

Do we have that separation in the logic handled at conversion?

I don't think this is feasible. When the LOG-ENTRY-TYPES is assigned, it can be assigned from any character expression. Since we cannot rely upon this to be a string literal, we cannot know the value of LOG-ENTRY-TYPES until runtime. This means that only the runtime can know what needs to be logged.

More importantly, as far as I know, the logging can all be hidden inside the FWD runtime. Even things like 4GLTrace are not logging each line of code in the 4GL program, it is logging in response to various invocation mechanisms like the RUN statement. Each of these has some backing implementation in FWD and inside those backing runtime locations we will have to put logging code that matches the same result as the 4GL would generate. This means the timing of when the output occurs, outputting only that the exact same "event" that as the 4GL would log, ensuring that the format of the log entry is the same. I don't expect the converted code to change as a result of this task, since we already have the conversion of these 4GL elements implemented.

LOG-MANAGER:WRITE-MESSAGE supports by default text up to 15000 characters (actually it should be less, since that is for the whole statement in 4GL). If more than that it throws:

** More than 15000 characters in a single statement--use -inp parm. (135)
** .\test.p Could not understand line 16. (193)
** Unable to run startup procedure test.p. (492)

There is the param -inp described here as:

The number of characters allowed in a single ABL statement. The default is 15000 characters.

I cannot find anything related to it in our code. I guess we don't have that 4GL limitation. Do we show the same error when LOG-MANAGER:WRITE-MESSAGE tries to write more than 15000 chars? If yes, then we'll have to also add support for startup command -inp.

Do we show the same error when LOG-MANAGER:WRITE-MESSAGE tries to write more than 15000 chars? If yes, then we'll have to also add support for startup command -inp.

For now, I don't see a reason to implement this limitation. Since this is only present depending on command line arguments, it is not something that can be assumed to always exist. If the error doesn't exist, the only consequence is there is no error. I don't see any functional reason that application code would need to fail if log entries were over 15000 characters long. For now, ignore this.

• -logthreshold activating rotation and setting the max file size in bytes,
• -numlogfiles defining the max number of log files to keep. The rest are removed regularly.

Both of them don't have setters and cannot be set programmatically which makes sense, otherwise changing rotation logic runtime would be a strange one. The problem is testing it automatically (in our setup). That's why there is nothing related to rotation in testcases. A very substantial portion of the whole logic is verifying startup params and delivering rotation based on that.

We need a separate script for each test to run it with the same predefined startup args in both Progress envs (where it can be started manually) and in our own pre-configured VM. For most cases VM is actually an overkill, a lightweight Docker container can run a lot of tests quickly in batch / appserver - agent mode. But the key here is to have pairs of script - test, where the script starts the test in a client with the expected startup args.

Log message chars limit
Actually on second thought keeping the 15000 chars per message limit makes sense in the context of file rotation, where the allowed min file size is 500_000 bytes. I guess there might have been some memory concerns taken in consideration when Progress made it a requirement for statements, but logging big chunks of text in small files might not be a good idea either. Even if we don't like their limit, we still need to impose a common sense one - message.length < logThreshold (and in that case we'll have to get into charset as well), so I would advice to keep the original one.

• multiple sessions / processes writing to the same log file, when rotation is not enabled (-logthreshold not defined).
• only one session / process writing to the log files, when rotation is enabled. If process A starts with -clientlog client.log -logthreshold 500000 and process B starts after that with the same -clientlog client.log -logthreshold 500000. Process A is the only one able to write to files in the sequence like client.000001.log, while process B doesn't show any signs of error and just continues without logging. Check here . It's better documented somewhere else, but I cannot find it now. Anyways I've tested it and it's confirmed.

Our implementation of LOG-MANAGER runs purely on the server. When a client (gui, chui, batch) hits StandardServer it's on a new thread created specifically for that client. LegacyLogOps delivers a new instance of LegacyLogManagerImpl using the mechanism of ThreadLocal. Accessing LOG-MANAGER through LegacyLogOps makes it effectively singleton for the thread.

So in 4GL a session is a process, in FWD a session is a thread. By default having multiple sessions / threads writing to the same file without synchronization leads to broken files. The original no-rotation behavior in 4GL allows writing to the same file though. Also the other part is allowing only one session to write log files when rotation is enabled - we still need a common code to orchestrate that. Logging is a high throughput process and I'm definitely not thinking of creating a bottleneck, but it might be a good idea to still do something about it. I don't have the solution right now, I need to do some experiments to see what will work, especially with ThreadLocal as it is implemented. But let me know what are your thoughts?

Close log on client exit
Somewhat related to multi-threading is the solution I've implemented to closing the LOG-MANAGER, when the client exits. I've noticed that's when ContextLocal gets cleaned up, so I've added a cleanup '@Override for local (ContextLocal<WorkArea>) in LegacyLogOps that calls LOG-MANAGER:CLOSE-LOG.

Current clientlog implementation and -debugalert

Currently the code uses -clientlog startup param to enable logging of error messages that should be enabled by a different startup param -debugalert (i.e. SESSION:DEBUG-ALERT) and further expanded by -errorstack (i.e. SESSION:ERROR-STACK-TRACE).

-debugalert enables auto logging of:

ABL stack trace for error messages (ABL errors and .NET Exceptions) and Alert-box messages

-errorstack:

includes the contents of the CallStack property for the unhandled error

We have both of these behaviors now coming directly with -clientlog and independent of the parameters/configs.

Currently these logs are generated client-side (as far as I understand) in ThinClient and AlertBoxGuiImpl, but they seem to root from ErrorManager.

The proper LOG-MANAGER implementation obviously interferes with that use of 4GL -clientlog param. What we have can be covered by the proper implementation of -debugalert and -errorstack. Instead of trying to sneak in two different approaches I would recommend that we stay away from adding multiple responsibilities to something with a clear definition in 4GL and instead focus on completing -debugalert and -errorstack behavior depending on LegacyLogManagerImpl.

I will need a few days to come up with solution for it. Do you want me to proceed with it and under what task?

P.S. This also involves changes to logging level and entry types, which are set automatically with -debugalert presence.

P.S.S. The easiest quickest patch to complete #5753 would be to just switch the dependency from -clientlog to -debugalert (with a hardcoded path to the log file) and open a -debugalert separate task (maybe #4065 or this one #3853) to migrate the logic to LOG-MANAGER.

Galya Bogdanova wrote:

P.S.S. The easiest quickest patch to complete #5753 would be to just switch the dependency from -clientlog to -debugalert (with a hardcoded path to the log file) and open a -debugalert separate task (maybe #4065 or this one #3853) to migrate the logic to LOG-MANAGER.

I've just added a new startup param -debugalertlog and switched the file name (-clientlog) passed to ThinClient#initClientLog by ClientCore. The change is quite simple and keeps both log files until proper -debugalert handling is implemented. Pushed to 5753a (commit 14468).

Galya Bogdanova wrote:

open a -debugalert separate task (maybe #4065 or this one #3853) to migrate the logic to LOG-MANAGER.

I'm fine with continuing work under #5753 as that's where this got broken, but the changes will get beefy and I'm not sure how easy it will be for a code review if I continue adding to it.

From Galya via email:

I've tested gui, batch, web gui clients and they are working well with LOG-MANAGER. But I've noticed appserver (scheduled batch) doesn't use LOG-MANAGER. It's not related to the startup command, because log manager should work with programmatically set configs (which it doesn't now). It might be that log manager initialization in StandardServer#standardEntry somehow doesn't affect the instance appserver uses. I don't completely understand what's going on after AppServerManager.startAppServer().

Does the 4GL have an implicit set of settings for LOG-MANAGER in an appserver process? If so, then we need to implement the equivalent.

Constantin will have more thoughts on this.

Greg Shah wrote:

From Galya via email:

I've tested gui, batch, web gui clients and they are working well with LOG-MANAGER. But I've noticed appserver (scheduled batch) doesn't use LOG-MANAGER. It's not related to the startup command, because log manager should work with programmatically set configs (which it doesn't now). It might be that log manager initialization in StandardServer#standardEntry somehow doesn't affect the instance appserver uses. I don't completely understand what's going on after AppServerManager.startAppServer().

For appservers, any initialization code needs to be written in Agent.prepare. This is a duplicate of any initialization code which you add to StandardServer.standardEntry, after the AppServerManager.startAppServer() test, for non-appserver clients.

Greg Shah wrote:

For logthreshold and numlogfiles and the other items from #3853-19, we should be able to configure these via 2 mechanisms:

1. directory.xml
   • We probably need some kind of override for setting the server-wide default values.
   • We definitely need account/group level control over the same.
   • I think this can be done with our normal multi-stage lookup process (see Utils.getDirectoryNode*() methods when DirScope.BOTH is passed).
2. bootstrap configuration (which can be in the bootstrap config file and/or on the command line)

Constantin: Any thoughts on this?

Yes, I think that's about right. We should consider having similar/identical names for these settings, for both directory and bootstrap cases. Galya: please post what logmanager related config needs to added.

Constantin Asofiei wrote:

Galya: please post what logmanager related config needs to added.

I should have made the necessary changes on branch 5753a.

Having no setters for rotation related configs, means tests should rely on configurations outside of them, which is not easy to automate without a dedicated process.

Greg Shah wrote:

Does the 4GL have an implicit set of settings for LOG-MANAGER in an appserver process? If so, then we need to implement the equivalent.

Constantin will have more thoughts on this.

Update: The issue is not in the configs or LOG-MANAGER initialization. If all relevant startup params are removed LOG-MANAGER should still get enabled by this procedure and should produce logs:

LOG-MANAGER:LOGFILE-NAME = "/home/gbb/testcases/deploy/bgr.log".
LOG-MANAGER:WRITE-MESSAGE("Hello ABL").

It does for all other types of clients, only appserver_process doesn't produce anything. So I'm thinking there is something wrong with how the LOG-MANAGER handle is used in this mode, but I have no clue what to look for.

P.S. I compared the client logs of the scheduled batch (appserver_process) and web and it seems web starts ContextHandler, while appserver_process doesn't. The LOG-MANAGER handle accesses the instance of LegacyLogManagerImpl through LegacyLogOp's ContextLocal<WorkArea>, so it seems to be related.

A few observations in relationship to max log message length (tested):

• By default statement length is limited to 15000 characters.
• With -inp (or Input Characters) statement length can be set to max 2147483647 characters (~2GB).
• But LOG-MANAGER:WRITE-MESSAGE works for up to 32767 characters text (32K bytes per record). After that messages are completely ignored. That limit is documented in Inputoutput-limits . A side notice: Java FileWriter (I use in LegacyLogManagerImpl implementation) uses UTF-16 by default and that will be 64K bytes.
• Logging alerts from MESSAGE VIEW-AS ALERT-BOX is limited to 3000 characters. Bigger messages are cut to the 3000 character.
• With messages of type ALERT-BOX having length more than 65000 characters, the app crashes consistently or sometimes gives stget: out of storage (1450) error.

The conclusion is: Although Progress have the -inp startup param, the apps have other limitations and perform poorly with very long full texts.
I'm about to implement -inp. Do we want also the 32767 chars limit for LOG-MANAGER:WRITE-MESSAGE? If not, I'll still have to implement the common sense validation of checking for rotation file size limit (logRecord.getBytes().length > logThreshold).

Do we want also the 32767 chars limit for LOG-MANAGER:WRITE-MESSAGE?

Yes. Also, please implement the limit of 3000 in MESSAGE VIEW-AS ALERT-BOX.

With messages of type ALERT-BOX having length more than 65000 characters, the app crashes consistently

Is this different than MESSAGE VIEW-AS ALERT-BOX? Or is this just the case where the 4GL handles the really long messages badly and doesn't get the chance to truncate to 3000?

Greg Shah wrote:

Our implementation of LOG-MANAGER runs purely on the server.

It is certainly preferable to do this. However, we know there can be cases when this is simply wrong and the log files must be on the client side. We need to support both.

I will figure out ways to implement it both server-side and client-side, when I see the case. I still haven't got into implementing log entry types (#3853), so that might be where it needs to be extended. We'll discuss it further, when I get familiar with these requirements.

LegacyLogOps delivers a new instance of LegacyLogManagerImpl using the mechanism of ThreadLocal.

We should not use ThreadLocal. It is not guaranteed that all log operations will be on the same thread. I think that was done as a quick and dirty approach, but we need this to be ContextLocal.

It is ContextLocal, which creates an instance of the log manager wrapper through class Fallback extends ThreadLocal<T> get() for standalone clients and some cases in server clients. It's guaranteed that different clients will operate on different threads with different instances of the log manager.
But maybe you mean one client might operate on multiple threads? 4GL apps are single threaded. Do you mean that FWD implementation is different?

This would work if the message posted into the queue was an object that stored the log entry as well as the log file to be written to.

This sounds good at first, but there is a ton of validation and error messages going on in LegacyLogManagerImpl and the queue will have to be quite smart (taking over log manager's responsibilities) or sending back a lot of feedback.

Greg Shah wrote:

Is this different than MESSAGE VIEW-AS ALERT-BOX? Or is this just the case where the 4GL handles the really long messages badly and doesn't get the chance to truncate to 3000?

It's still MESSAGE VIEW-AS ALERT-BOX. When the message is 65000+ chars the whole app crashes. When it's less, it's processed and truncated to 3000 in the log file.

Greg Shah wrote:

We must solve this properly. The behavior needs to match the 4GL implementation while implementing full thread-safety.

I'll get back to you with some options.

It is ContextLocal, which creates an instance of the log manager wrapper through class Fallback extends ThreadLocal<T> get() for standalone clients and some cases in server clients.

We don't really use the standalone mode. It will probably be removed at some point. As long as ContextLocal is used, it will be correct on the server-side.

But maybe you mean one client might operate on multiple threads? 4GL apps are single threaded. Do you mean that FWD implementation is different?

Yes, FWD is different. We simulate single-threaded mode in a multi-threaded environment. There are 2 modes for a non-virtual client session: conversation mode and dispatcher mode. In conversation mode, all normal processing happens on the "conversation" thread, which is a kind of server-side dedicated "main" thread for the session. However, even in conversation mode there are still ways that code can be invoked on non-conversation threads in a session. This mostly happens in response to an asynchronous interruption like CTRL-C in a ChUI session which generates a STOP condition. In non-conversation mode, we process all logic on dispatcher threads so it can be a different thread each time. You can have a mixture of conversation mode and dispatcher mode sessions in the same server, it is an attribute that is defined in the bootstrap config at the moment the session is started.

Understanding FWD Threading has some useful information related to this.

This would work if the message posted into the queue was an object that stored the log entry as well as the log file to be written to.

This sounds good at first, but there is a ton of validation and error messages going on in LegacyLogManagerImpl and the queue will have to be quite smart (taking over log manager's responsibilities) or sending back a lot of feedback.

I would think that the LegacyLogManagerImpl would do all the work until it decides that it actually needs to write a message out, then it can post to the queue. But you will know better as you analyze things.

Is this different than MESSAGE VIEW-AS ALERT-BOX? Or is this just the case where the 4GL handles the really long messages badly and doesn't get the chance to truncate to 3000?

It's still MESSAGE VIEW-AS ALERT-BOX. When the message is 65000+ chars the whole app crashes. When it's less, it's processed and truncated to 3000 in the log file.

OK, then this one is "easy" since we don't need to replicate their crashes. :)

Logging level rules:

4GL setter cannot be used to disable logging by LOG-MANAGER:LOGGING-LEVEL = 0.. This code doesn't change the logging level.

I'm trying to find the difference in the log files when SESSION:ERROR-STACK-TRACE (-errorstack) is enabled, but for now without success. It is supposed to include:

the contents of the CallStack property for the unhandled error.

A certain procedure test.p throws an error in a nested function throwerrornested called by another function throwerror. This is the log record:

pro -b -p test.p -clientlog "test.log"

[23/01/12@12:24:22.580+0100] P-002940 T-013736 1 4GL -- (Procedure: 'throwerrornested test.p' Line:14) Connection failure for host localhost port 5162 transport UDP. (9407)

pro -b -p test.p -clientlog "test.log" -debugalert

[23/01/12@12:23:45.153+0100] P-007656 T-004072 1 4GL -- Connection failure for host localhost port 5162 transport UDP. (9407)
[23/01/12@12:23:45.153+0100] P-007656 T-004072 1 4GL -- ** ABL Debug-Alert Stack Trace **
[23/01/12@12:23:45.153+0100] P-007656 T-004072 1 4GL -- --> throwerrornested test.p at line 14  (.\test.p)
[23/01/12@12:23:45.153+0100] P-007656 T-004072 1 4GL --     throwerror test.p at line 19  (.\test.p)
[23/01/12@12:23:45.153+0100] P-007656 T-004072 1 4GL --     test.p at line 44  (.\test.p)

The problem is pro -b -p test.p -clientlog "test.log" -debugalert -errorstack returns the same as pro -b -p test.p -clientlog "test.log" -debugalert. How is this CallStack property different from ABL Debug-Alert Stack Trace? Any idea what I can try to produce it?

Marian: Can you offer any guidance?

Greg Shah wrote:

Marian: Can you offer any guidance?

• -errorstack (session:error-stack-trace) has no effect on the client log (log manager), if enabled it will just attach the stack trace (full) to the error object CallStack when catch is used (no effect on standard error handling, no-error/error-status).
• -debugalert (session:debug-alert) does affect the client log and it is mentioned both on the debugalert and clientlog the fact that when that is set to true the stack trace (top entry only) will be written to the log file, not the full trace and that is not saved in the generated error object CallStack.

Bref, using -errostack has no effect on the client log so don't bother with it in this case.

Marian Edu wrote:

Bref, using -errostack has no effect on the client log so don't bother with it in this case.

Thank you for the confirmation. This is what I observe as well. It's just that the documentation mixes both UI and clientlog and sounds misleading. Good that we cleared this up.

When -clientlog or LOG-MANAGER:LOGFILE-NAME is defined logging level 1 is always enabled (except if explicitly set to 0 on startup with -logginglevel 0 or value of startup param -logentrytypes was invalid). Logging level 1 creates log records for all types of MESSAGE "" VIEW-AS ALERT-BOX and unhandled errors.

Example procedure lvl1.p:

DEF VAR h AS HANDLE NO-UNDO.

FUNCTION ThrowErrorNested RETURNS INTEGER ():
  CREATE SERVER h.
  h:CONNECT("").
  RETURN 1.
END.

FUNCTION ThrowError RETURNS INTEGER ():
  RETURN ThrowErrorNested().
END.

MESSAGE "MESSAGE" VIEW-AS ALERT-BOX MESSAGE.
MESSAGE "QUESTION" VIEW-AS ALERT-BOX QUESTION.
MESSAGE "INFORMATION" VIEW-AS ALERT-BOX INFORMATION.
MESSAGE "ERROR" VIEW-AS ALERT-BOX ERROR.
MESSAGE "WARNING" VIEW-AS ALERT-BOX WARNING.
MESSAGE "GENERIC" VIEW-AS ALERT-BOX.

ThrowError().

Logs produced when run with pro -b -p lvl1.p -clientlog lvl1.log:

[23/01/13@14:29:59.301+0100] P-008112 T-008220 1 4GL -- Logging level set to = 1
[23/01/13@14:29:59.358+0100] P-008112 T-008220 1 4GL -- MESSAGE
[23/01/13@14:29:59.358+0100] P-008112 T-008220 1 4GL -- QUESTION
[23/01/13@14:29:59.358+0100] P-008112 T-008220 1 4GL -- INFORMATION
[23/01/13@14:29:59.358+0100] P-008112 T-008220 1 4GL -- ERROR
[23/01/13@14:29:59.358+0100] P-008112 T-008220 1 4GL -- WARNING
[23/01/13@14:29:59.358+0100] P-008112 T-008220 1 4GL -- GENERIC
[23/01/13@14:29:59.387+0100] P-008112 T-008220 1 4GL -- (Procedure: 'ThrowErrorNested lvl1.p' Line:5) Connection failure for host localhost port 5162 transport UDP. (9407)
[23/01/13@14:29:59.393+0100] P-008112 T-008220 1 4GL -- (Procedure: 'ThrowErrorNested lvl1.p' Line:5) Application server connect failure. (5468)

Logs produced when run with pro -b -p lvl1.p -clientlog lvl1.log -debugalert:

[23/01/13@14:30:41.274+0100] P-013624 T-012048 1 4GL -- Logging level set to = 1
[23/01/13@14:30:41.341+0100] P-013624 T-012048 1 4GL -- MESSAGE
[23/01/13@14:30:41.341+0100] P-013624 T-012048 1 4GL -- ** ABL Debug-Alert Stack Trace **
[23/01/13@14:30:41.341+0100] P-013624 T-012048 1 4GL -- --> lvl1.p at line 13  (.\lvl1.p)
[23/01/13@14:30:41.341+0100] P-013624 T-012048 1 4GL -- QUESTION
[23/01/13@14:30:41.341+0100] P-013624 T-012048 1 4GL -- ** ABL Debug-Alert Stack Trace **
[23/01/13@14:30:41.341+0100] P-013624 T-012048 1 4GL -- --> lvl1.p at line 14  (.\lvl1.p)
[23/01/13@14:30:41.341+0100] P-013624 T-012048 1 4GL -- INFORMATION
[23/01/13@14:30:41.341+0100] P-013624 T-012048 1 4GL -- ** ABL Debug-Alert Stack Trace **
[23/01/13@14:30:41.341+0100] P-013624 T-012048 1 4GL -- --> lvl1.p at line 15  (.\lvl1.p)
[23/01/13@14:30:41.341+0100] P-013624 T-012048 1 4GL -- ERROR
[23/01/13@14:30:41.341+0100] P-013624 T-012048 1 4GL -- ** ABL Debug-Alert Stack Trace **
[23/01/13@14:30:41.341+0100] P-013624 T-012048 1 4GL -- --> lvl1.p at line 16  (.\lvl1.p)
[23/01/13@14:30:41.341+0100] P-013624 T-012048 1 4GL -- WARNING
[23/01/13@14:30:41.342+0100] P-013624 T-012048 1 4GL -- ** ABL Debug-Alert Stack Trace **
[23/01/13@14:30:41.342+0100] P-013624 T-012048 1 4GL -- --> lvl1.p at line 17  (.\lvl1.p)
[23/01/13@14:30:41.342+0100] P-013624 T-012048 1 4GL -- GENERIC
[23/01/13@14:30:41.342+0100] P-013624 T-012048 1 4GL -- ** ABL Debug-Alert Stack Trace **
[23/01/13@14:30:41.342+0100] P-013624 T-012048 1 4GL -- --> lvl1.p at line 18  (.\lvl1.p)
[23/01/13@14:30:41.361+0100] P-013624 T-012048 1 4GL -- Connection failure for host localhost port 5162 transport UDP. (9407)
[23/01/13@14:30:41.361+0100] P-013624 T-012048 1 4GL -- ** ABL Debug-Alert Stack Trace **
[23/01/13@14:30:41.361+0100] P-013624 T-012048 1 4GL -- --> ThrowErrorNested lvl1.p at line 5  (.\lvl1.p)
[23/01/13@14:30:41.361+0100] P-013624 T-012048 1 4GL --     ThrowError lvl1.p at line 10  (.\lvl1.p)
[23/01/13@14:30:41.361+0100] P-013624 T-012048 1 4GL --     lvl1.p at line 20  (.\lvl1.p)
[23/01/13@14:30:41.368+0100] P-013624 T-012048 1 4GL -- Application server connect failure. (5468)
[23/01/13@14:30:41.368+0100] P-013624 T-012048 1 4GL -- ** ABL Debug-Alert Stack Trace **
[23/01/13@14:30:41.368+0100] P-013624 T-012048 1 4GL -- --> ThrowErrorNested lvl1.p at line 5  (.\lvl1.p)
[23/01/13@14:30:41.368+0100] P-013624 T-012048 1 4GL --     ThrowError lvl1.p at line 10  (.\lvl1.p)
[23/01/13@14:30:41.368+0100] P-013624 T-012048 1 4GL --     lvl1.p at line 20  (.\lvl1.p)

Currently ThinClient#clientLog() doesn't log these. There seem to be several conditions up in the call stack that seem to interfere with this function being called. So the LOG-MANAGER implementation for logging level one will not rely much on what's already in the code.

I've found an unexpected behavior with batch execution. stdout is displayed using ErrorManager.displayError(lineOut); in com.goldencode.p2j.ui.client.chui.driver.batch.BatchPrimitives#updateScreen() L276. That causes our implementation of LOG-MANAGER to write all stdout (display, etc.) as errors in the log files in batch. Is ErrorWriterBatch used as the default screen writer for batch?
This is what ErrorWriterBatch#displayError() does (as of active branch 5753b):

113      if (client != null && client.isRedirected())
114      {
115         client.displayErrorMessage(errmsg, false, null, logCallStack);
116      }
117      else
118      {
119         ErrorManager.writeLog(errmsg, logCallStack);
120      }
121
122      if (PlatformHelper.isUnderWindowsFamily() && !isBatchInBackground() && !FileChecker.isConsoleRedirected())
123      {
124         // TODO: In Windows the native message box should be displayed here.
125      }
126
127      // then log it to redirected console
128      System.out.println(errmsg);

I would like to replace the call in BatchPrimitives#updateScreen() with System.out.println(lineOut);. Who can confirm if it's safe?

Note: To check if entry types are case-sensitive in configs.

The tests Constantin did for #5701#note-86 made me think about the appserver agent logs.

The implementation in #5753 is as follows: By default no log files are generated. LOG-MANAGER should be enabled by configuring a log file name for the appserver_process:

  <node class="container" name="">
    <node class="container" name="server">
      <node class="container" name="default">
          <node class="container" name="appserver_process">
            <node class="container" name="clientConfig">
              <node class="string" name="cfgOverrides">
                <node-attribute name="value" value="client:cmd-line-option:clientlog=appserver_process.log"/>
              </node>
            </node>
          </node>
      </node>
    </node>
  </node>

All other configs applicable to LOG-MANAGER are available for as described in Logs wiki. All agents of the appserver will write to the same log files as it is in OE.

• review if current cfgOverrides are compliant to AppServer Agent Logging Setting properties ; In OE the configs are entered in the graphical env for setting up appservers;
• subsystem code AS as in Logs;
• take into consideration that LOG-MANAGER handles are dealt with in a specific way, when used in procedures running on appservers, because the agent itself already has a log file. Check the log in Logs (**LOGFILE-NAME is not a setable attribute for PSEUDO-WIDGET.). This behavior should be cross-checked with OE and modifications applied;
• consider removing ouputToFile for appservers, because after #7236 is fixed, it should contain the same output as the appserver log file.

Answering to #5753#note-113 :

Constantin Asofiei wrote:

From this, we know:

• changing LOGFILE-NAME does not raise an ERROR condition on the appserver
• LOGGING-LEVEL can be set
• State-reset does not change the LOG-MANAGER to its initial value - I think what needs to be done in FWD is to:
  • in Agent.prepare, if Agent.logManager (a new field) is null, initialize the LogManager's context-local state and save the this instance at Agent.logManager
  • in Agent.prepare, if Agent.logManager (a new field) is not null, initialize the LogManager's context-local state with the saved one

Does this make sense? We will need to check the other LOG-MANAGER attributes (beside LOGGING-LEVEL and LOGFILE-NAME) to see if they can be changed on the appserver.

• On appserver LOGFILE-NAME doesn't change anything, but shows a warning message, it's not an error indeed.
• LOGGING-LEVEL can be set, but does it take actual effect is something to consider when entry types with higher level log levels are tested and implemented.
• State-reset - What I implemented in 5753d r14519 is a different approach with the same result - on every Agent.prepare LegacyLogManagerImpl.initiate is called and if it's a new instance, then the flag isInstantiated is false and the work gets done.
• The other attributes are:
  • logentrytypes - not fully implemented yet.
  • numlogfiles, logthreshold - don't have setters, settable only with startup configs.

• srvrLogFile - by default {WorkPath}\%appservername%.server.log.
• srvrLogAppend - by default 1.
• srvrLoggingLevel - by default Basic or 2.
• srvrLogEntryTypes - by default ASPlumbing,DB.Connects activated.
• srvrNumLogFiles - by default 3.
• srvrLogWatchdogInterval ? - by default 60
• srvrLogThreshold - by default 0
• srvrLogEntries - ? by default 0

LOG-ENTRY-TYPES and LOGGING-LEVEL are LOG-MANAGER attributes that can be changed in the internal procedure running on the appserver agent, but they don't change the configurations in the OE Explorer. It's still to be determined if this is a long lived change and if it affects all agents running at that time on the appserver as well as those running after the disconnect.

Here are my startup args tests. Now with focus on error thrown or shown. The current impl will have to be revised.

msg.p contains only MESSAGE "TEST".. If TEST shows on the screen, it means the client doesn't thrown an error and the execution continues.

pro -p msg.p -b
pro -p msg.p -clientlog msg.log -b
TEST

pro -p msg.p -clientlog /invalid/path -b
Cannot open log file /invalid/path, errno 3 (11076)
TEST

pro -p setname.p -b
(set programmatically) LOG-MANAGER:LOGFILE-NAME="/invalid/path".
Cannot open log file /invalid/path, errno 3 (11076)
** Unable to open file for PSEUDO-WIDGET. (4487)
TEST

IN APPSERVER
pro -p setnameappserver.p -b
(set programmatically) LOG-MANAGER:LOGFILE-NAME="name.log".
LOGFILE-NAME is not a setable attribute for PSEUDO-WIDGET. (4052)
TEST

pro -p msg.p -clientlog msg.log -logentrytypes Invalid -b
pro -p msg.p -logentrytypes Invalid -clientlog msg.log -b
Ignoring unknown log entry type: Invalid (11069)
TEST

pro -p msg.p -logentrytypes 4GLTrace:1 -clientlog msg.log -b
Logging level for 4GLTrace must be 2 or higher (11071)
TEST

pro -p msg.p -logentrytypes 4GLTrace -clientlog msg.log -logginglevel 1 -b
Logging level greater than 1 must be specified either for 4GLTrace or for all types by using -logginglevel. (11072)
TEST

pro -p msg.p -logentrytypes 4GLTrace -clientlog msg.log -b
--
(set programmatically) 
LOG-MANAGER:LOGGING-LEVEL=1.
MESSAGE LOG-MANAGER:LOGGING-LEVEL.
MESSAGE "TEST".
--
2
TEST

pro -p msg.p -clientlog msg.log -logginglevel abc -b
The -logginglevel parameter requires a numeric argument. (11996)

pro -p msg.p -clientlog msg.log -logginglevel -1 -b
pro -p msg.p -clientlog msg.log -logginglevel 2147483648 -b
The -logginglevel parameter has too many digits. (5049)

pro -p setloglevel.p -b -clientlog msg.log -b
(set programmatically) LOG-MANAGER:LOGGING-LEVEL=-1.
**Attribute LOGGING-LEVEL for the PSEUDO-WIDGET has an invalid value of -1. (4057)
TEST

pro -p setloglevel.p -b -clientlog msg.log -b
(set programmatically) LOG-MANAGER:LOGGING-LEVEL=2147483648.
**Attribute LOGGING-LEVEL for the PSEUDO-WIDGET has an invalid value of -2147483648. (4057)
TEST

pro -p msg.p -logginglevel 1 -b
Parameters for logging were specified but -clientlog was not set. Logging parameters will be ignored. Specify -logginglevel 0 if you want to keep logging disabled at startup. (11068)
TEST

pro -p setloglevel.p -b
(set programmatically) LOG-MANAGER:LOGGING-LEVEL=5.
**Cannot set attribute LOGGING-LEVEL because log file name was not specified at startup. (11078)
TEST

pro -p setloglevel.p -b
(set programmatically) LOG-MANAGER:LOGGING-LEVEL=5.

pro -p msg.p -clientlog msg.log -logthreshold -1 -b
pro -p msg.p -clientlog msg.log -logthreshold 2147483648 -b
The -logthreshold parameter has too many digits. (5049)

pro -p msg.p -clientlog msg.log -logthreshold abc -b
The -logthreshold parameter requires a numeric argument. (11996)

pro -p msg.p -clientlog msg.log -logthreshold 499999 -b
-logthreshold must be set to a value between 500000 and 2147483647 (11065)

pro -p msg.p -clientlog msg.log -numlogfiles -1 -b
pro -p msg.p -clientlog msg.log -numlogfiles 2147483648 -b
The -numlogfiles parameter has too many digits. (5049)

pro -p msg.p -clientlog msg.log -numlogfiles 1 -b
-numlogfiles cannot be set to 1 (11067)

pro -p msg.p -clientlog msg.log -numlogfiles 1000000 -b
-numlogfiles cannot be set to a value greater than 999999 (14416)

pro -p clearlog.p -b
(programmatically) LOG-MANAGER:CLEAR-LOG().
Cannot clear log because there is no log file open (14333)
TEST

pro -p writemsg.p -b
(programmatically) LOG-MANAGER:WRITE-MESSAGE("MSG").
Cannot write message to log, as there is no log open (14332)
TEST

Note: This task should include proper implementation of basic-logging that is already supported in the 4GL syntax.

Greg Shah wrote:

Galya B wrote:

Note: This task should include proper implementation of basic-logging that is already supported in the 4GL syntax.

Do you mean logging-level 2 (basic) or query:basic-logging?

https://docs.progress.com/bundle/abl-reference/page/BASIC-LOGGING-attribute.html

QUERY:BASIC-LOGGING is already listed in #3853-1. Whether we implement a new set of logging instrumentation for it or we repurpose existing query logging, we will have to determine later.

8661b covers ASPlumbing on level 1 and 2 in the new PASOE implementation.

I've noticed the persist package excessively uses methods in ErrorManager that don't create legacy logs. After 8661b is merged a better instrumentation will be available to developers to add legacy logs. Then request the DB developers to go over all errors and properly log them.

Responses to questions from Tomasz (sent via email):

Identified logging levels, reviewed logger code.

Is there way any other then just running 4gl examples ?

This is the way. We must have our own tests that we can run at will to define the logging functionality. We already do have some automated tests (in Testcases see tests/log_manager/) but it is likely that these are not complete. Please extend those tests as needed to add new areas of instrumentation.

How can I know all logs are finally generated ?

It is unknowable.

Can I get logs from customer applications to find a baseline ?

We can ask for some logs from multiple customers to help identify example instrumentation points. The problem is that we cannot rely upon those for testing since they will have been created by a process that cannot be duplicated. I expect that we need to implement our own automated tests to fill in our gaps and it is our test suite that will define if we pass testing or not.

I will make the customer requests.

I've started with testcases examples (tests/logmanager).

There is a problem in current trunk with conversion of testcases examples:
We have: define private variable hObj as handle no-undo.

• hObj:handle no-error. is converted to silent(() -> hObj); which is not compilable code, works when replaced with assignment like testHandle = hObj:handle no-error.
• hObj:handle = ? no-error. is converted to silent(() -> hObj.unwrap().readOnlyError("handle", new WrappedResource())); which is not compilable code, works if unknown is replaced with handle reference hObj:handle = testHandle no-error.

Will skip this for now, will fix that later.

Greg Shah wrote:

Can I get logs from customer applications to find a baseline ?

We can ask for some logs from multiple customers to help identify example instrumentation points. The problem is that we cannot rely upon those for testing since they will have been created by a process that cannot be duplicated. I expect that we need to implement our own automated tests to fill in our gaps and it is our test suite that will define if we pass testing or not.

I will make the customer requests.

Do we have anything ?

Tomasz Domin wrote:

I've started with testcases examples (tests/logmanager).

I've executed testcases/tests/logmanager in OE 11.7 - There are 27 tests failing out of 63 (or even 36 when running with ant + PCT). It may be due to differences of the OE version the tests were written for.

Based on answers from the customers - I think no customer depend on logs for transaction processing. What I mean - there is no application business logic that depend on parsing logs - they are only used for debugging purposes.

Greg - questions:
I have an access to OE 11.7 - should I update tests/logmanager tests to make them work ? Which OE version should be supported ?
Some of the tests are checking if generated logs are exactly the same as generated by OE, but that may be an overkill for debugging purposes - it would make if logs were used as a part of application business logic. What should be accuracy of logs generated by FWD ? Should it be character-level accuracy, or is it sufficient to report roughly the same information (if available) for similar situations?

I have an access to OE 11.7 - should I update tests/logmanager tests to make them work ? Which OE version should be supported ?

There is no single supported OE version. If there are OE version-speciifc differences, then the test should be written to check the version and match appropriately. In OE, this can be done using the PROVERSION built-in function.

If we need to implement something in FWD that is version specific, we use the equivalent EnvironmentOps.getVersion().

Some of the tests are checking if generated logs are exactly the same as generated by OE, but that may be an overkill for debugging purposes - it would make if logs were used as a part of application business logic. What should be accuracy of logs generated by FWD ?

By default, we assume that the log output should match character for character. If there is a good reason to deviate in specific cases, we will discuss them on a case-by-case basis.

Greg Shah wrote:

I have an access to OE 11.7 - should I update tests/logmanager tests to make them work ? Which OE version should be supported ?

There is no single supported OE version. If there are OE version-speciifc differences, then the test should be written to check the version and match appropriately. In OE, this can be done using the PROVERSION built-in function.

Does it mean I should make tests to complete successfully on the OE version I have access to using PROVERSION if needed ?

How could I know the differences having access only to single version of OE ?
Which version of OE tests/logmanager are written for ?

Tomasz Domin wrote:

Greg Shah wrote:

I have an access to OE 11.7 - should I update tests/logmanager tests to make them work ? Which OE version should be supported ?

There is no single supported OE version. If there are OE version-speciifc differences, then the test should be written to check the version and match appropriately. In OE, this can be done using the PROVERSION built-in function.

Does it mean I should make tests to complete successfully on the OE version I have access to using PROVERSION if needed ?

It means that any version specific code should be protected. If there is existing code that works on 11.6 or 10.2 or whatever, then protect that code and add conditions that will also work for whatever version you are testing (11.7 in your case).

In other words, don't delete the old code, just protect it and make additions for your version if needed.

How could I know the differences having access only to single version of OE ?
Which version of OE tests/logmanager are written for ?

Whatever was there before was working on 11.6.

Greg
While working on ABLUnit tests for LOG-MANAGER I had a major problem with resetting LOG-MANAGER state to defaults between tests.

ABLUnit tests are written in a way then can be run alone or as a part of a test suite.
In order to allow running as a part of suite there must be possibility to reset completely LOG-MANAGER to initial/default state between tests.

I started resetting LOG-MANAGER with following code:

LOG-MANAGER:LOGFILE-NAME = ? NO-ERROR.
LOG-MANAGER:LOG-ENTRY-TYPES = ? NO-ERROR.
LOG-MANAGER:LOGGING-LEVEL = ? NO-ERROR.

According to documentation by setting above values to UNKNOWN default values should be restored.

First problem was is that LOG-ENTRY-TYPES is not changeable if there is no LOGFILE-NAME set to a valid filename. I've solved that by opening a temporary log file only to allow LOG-ENTRY-TYPES change and in addition to allow flush pending logging leftovers before starting actual test.

Second problem was that LOG-ENTRY-TYPES were not truly reset to initial state by the above assignment, but it was not that straightforward to experience.
In case LOGGING-LEVEL for any LOG-ENTRY-TYPE in the current session was ever set to value 2 or higher that was remembered in the session (note that all ABLUnit tests are executed within the same session).
For example we had two tests one following the other - one was setting LOG-ENTRY-TYPES to "4glmessages:4", and the other test was setting "4gltrace:0" - which is illegal and reported as illegal with reported error, the surprise was that the resulting LOG-ENTRY-TYPES was ... "4gltrace:4" in the end despite all the errors reported. How come ? :) Note that 4gltrace:0 could not be used to reset LOGGING-LEVEL as it is illegal anytime.

It seems that setting 4glmessages:4 was implicitly resetting default LOGGING-LEVEL to 4. And default value was used in case illegal log level for given LOG-ENTRY-TYPE was specified. The problem I had was that default LOGGING-LEVEL was not reset with LOGGING-LEVEL = ? and I didnt know how to reset it. After spending a while on testing multiple options I've found that the only way to reset default LOGGING-LEVEL was setting LOGGING-LEVEL = 0

So I ended up with following reset procedure execute in ABLUnit test Before:

    method public void setUpClass():
        session:suppress-warnings = false.
// preserve old logging level
        loglevel = LOG-MANAGER:LOGGING-LEVEL. 
// open temporary file to be used as log file
        logFile = support.FileUtils:GetTempFile().
// use temporary log file to flush log-manager leftovers before starting actual testing
        log-manager:logfile-name = logFile.
// reset all default logging-levels for all entry-types
        LOG-MANAGER:LOGGING-LEVEL   = 0.
// reset log-entry-types to defaults
        log-manager:log-entry-types = ?.
// restore logging-level
        LOG-MANAGER:LOGGING-LEVEL   = loglevel.
// close temporary log
        log-manager:close-log() no-error.
// delete temporary log file
        os-delete value(logFile).
    end method.

Greg Shah wrote:

It means that any version specific code should be protected. If there is existing code that works on 11.6 or 10.2 or whatever, then protect that code and add conditions that will also work for whatever version you are testing (11.7 in your case).

In other words, don't delete the old code, just protect it and make additions for your version if needed.

Ok, I will do so for known differences between 11.7 and 11.6 - I will check OE version and act accordingly.

Whatever was there before was working on 11.6.

I did some changes to tests and I need to retest them on OE 11.6.

Another OE 11.7 difference:
You can set LOG-MANAGER:LOGGING-LEVEL only to a value greater than it was already set, unless you set it to level 2,3 or 4.
No so funny thing about it is that is is reported in logs Logging level set to = requested level, but actual LOG-MANAGER:LOGGING-LEVEL is left unchanged.

Greg
In order to pass one of tests I had to make FILE-INFO:FILE-SIZE to reread file size.
Was it static on purpose (performance ?) ?
File size was only set after initialization and was never updated no matter if underlying file has changed. That may lead to issues when integrating with other processes via files.

In order to pass one of tests I had to make FILE-INFO:FILE-SIZE to reread file size.
Was it static on purpose (performance ?) ?
File size was only set after initialization and was never updated no matter if underlying file has changed. That may lead to issues when integrating with other processes via files.

I think this was primarily done because we did not consider the alternative (that it is dynamic). I guess we didn't have any test code that showed that scenario. If in OE this is dynamic, then it should be dynamic in FWD.

Is there a standard way of resolving (as a reverse lookup) of current procedure name, line and method ?
I've found ProcedureManager.getProcedureHelper()._thisProcedure(), ProcedureManager.getRelativeName

For procedure name, this seems reasonable.

Constantin?

I didnt find anything related to reverse lookup of a line number.

We don't have this at runtime right now. What is the use case?

For transaction id I am using TransactionManager.getTransactionId

I'm not sure about this. That API is matches the 4GL feature DBTASKID. Is that what the 4GL LOG-MANAGER will report?

Greg Shah wrote:

I didnt find anything related to reverse lookup of a line number.

We don't have this at runtime right now. What is the use case?

To generate line like this: [25/11/17@13:44:01.199+0100] P-010784 T-002516 3 4GL 4GLTRANS BEGIN TRANS 4253 [TestSet4GLTrans tests.log_manager.TestLogEntryTypes 395]@

For transaction id I am using TransactionManager.getTransactionId

I'm not sure about this. That API is matches the 4GL feature DBTASKID. Is that what the 4GL LOG-MANAGER will report?

The same use case as above, 4253 looks like transaction number:
[25/11/17@13:44:01.199+0100] P-010784 T-002516 3 4GL 4GLTRANS BEGIN TRANS 4253 [TestSet4GLTrans tests.log_manager.TestLogEntryTypes 395]@

I need also following data:
Database connection options - for now I use only -H and -P generated out of selected ConnectionManager.connect parameters for:
[25/11/17@13:47:04.213+0100] P-002800 T-008764 2 4GL CONN Database tstcasesdb Options: (12699)

Database roles - for now its empty for:
[25/11/17@13:47:04.216+0100] P-002800 T-008764 4 4GL CONN User fwd-test Roles: SECUR_ADMIN AUDIT_ADMIN (12698)

Greg Shah wrote:

Is there a standard way of resolving (as a reverse lookup) of current procedure name, line and method ?
I've found ProcedureManager.getProcedureHelper()._thisProcedure(), ProcedureManager.getRelativeName

For procedure name, this seems reasonable.

Constantin?

Agreed.

Greg, Constantin
I have a question on a preferred way legacy logging should be implemented, which requires finding a proper places in FWD to generate logs from with "injected" code.
Until now I've only worked with runtime changes. But it may be needed to make conversion changes or a new AspectJ rules.
What is priority of each above ? Which one is preferred ?

Tomasz, if you need line numbers, look into how p2j.oo.lang.ProError.callStack is calculated (from the Java stacktrace).

For your last question: I would expect this to be added in the FWD runtime, not in the converted code. Please describe in short what needs to be logged.

Constantin Asofiei wrote:

Tomasz, if you need line numbers, look into how p2j.oo.lang.ProError.callStack is calculated (from the Java stacktrace).

For your last question: I would expect this to be added in the FWD runtime, not in the converted code. Please describe in short what needs to be logged.

Currently I need parameters to log 4GLTRACE like this, didnt find anything in FWD to get it, as functions are called direcly a pointcut (or conversion change) would be helpful.
Invoke dummyMethod "param1 2" [testInvokeMethod - tests.log_manager.log_entry_types.Test4glTraceEntry 156]@

And how would the 4GL code look like, which would produce these logs?

Note that every call (beside some exceptions for property getter or setter), FWD will go through BlockManager. And at that step, we know what is being executed.

Constantin Asofiei wrote:

And how would the 4GL code look like, which would produce these logs?

        do logLevel = 2 to 4:
            dummyMethod("param1", 2).
        end.

Note that every call (beside some exceptions for property getter or setter), FWD will go through BlockManager. And at that step, we know what is being executed.

Yes, but block manager does not process parameters, they are passed directly. I'd need to check metadata or call stack.

Tomasz Domin wrote:

Constantin Asofiei wrote:

And how would the 4GL code look like, which would produce these logs?

[...]

Note that every call (beside some exceptions for property getter or setter), FWD will go through BlockManager. And at that step, we know what is being executed.

Yes, but block manager does not process parameters, they are passed directly. I'd need to check metadata or call stack.

All parameters are defined via TypeFactory or UndoableFactory, plus special cases for dataset/temp-table[handle] and buffer. We can intercept it there, and record the parameters if the logging is enabled.

But it may be needed to make conversion changes or a new AspectJ rules.

Conversion changes, if really needed, are acceptable.

AspectJ is something to avoid unless there are really compelling reasons. Using AspectJ can kill performance and it is overcomplicated and hides away critical parts of the control flow of the code, making it difficult to reason about. It also complicates the build and IDE support. In a perfect world, we would not use AspectJ at all.

Constantin Asofiei wrote:

Tomasz Domin wrote:

Yes, but block manager does not process parameters, they are passed directly. I'd need to check metadata or call stack.

All parameters are defined via TypeFactory or UndoableFactory, plus special cases for dataset/temp-table[handle] and buffer. We can intercept it there, and record the parameters if the logging is enabled.

Thank you, it works - I just need to store values in some ContextLocal. Not good thing about it that this approach requires storing all function parameters values no matter if they will be printed or not in case Legacy Logging is enabled.

Tomasz Domin wrote:

Not good thing about it that this approach requires storing all function parameters values no matter if they will be printed or not in case Legacy Logging is enabled.

I assume this is some kind of 'development-level' logging which would not be in production envs. Otherwise the overhead will affect performance, and we need to ensure this work is done only and only if this level of the logging is enabled.

Constantin Asofiei wrote:

Tomasz Domin wrote:

Not good thing about it that this approach requires storing all function parameters values no matter if they will be printed or not in case Legacy Logging is enabled.

I assume this is some kind of 'development-level' logging which would not be in production envs. Otherwise the overhead will affect performance, and we need to ensure this work is done only and only if this level of the logging is enabled.

I've implemented an additional guard - isTracingEnabled which gives back information if there is 4GLTRACE at level 2 or higher enabled.

Is there a way to check in Block if class constructor has been called ?

Tomasz Domin wrote:

Is there a way to check in Block if class constructor has been called ?

You mean already called or 'currently executed'?

Constantin Asofiei wrote:

Tomasz Domin wrote:

Is there a way to check in Block if class constructor has been called ?

You mean already called or 'currently executed'?

currently executed in topLevelBlock
Actual methodName is class name, but I dont know if I can rely on this.
I have to exclude constructor from reporting method call tracing

• the pseudo-execute method for the class and super-classes
• the constructor

You can add a flag in BlockManager$WorkArea to track this execution; I don't think is easy otherwise to determine this.

Constantin Asofiei wrote:

See ControlFlowOps.initializeLegacyObject - there are two methods being called when instantiating:

• the pseudo-execute method for the class and super-classes
• the constructor

You can add a flag in BlockManager$WorkArea to track this execution; I don't think is easy otherwise to determine this.

That worked, thank you.
I have a problem with ProcedureManager.resolveClosestMethod(ProcedureHelper._thisProcedure) - its parameters depend on when from the function is called, there is no generic function - just return the current method - no matter if its function, external or internal procedure. Obviously I dont want to make any changes to FWD runtime.
The other thing sometimes ProcedureHelper._thisProcedure returns some plain objects :) not usable in ProcedureManager.resolveClosestMethod at all, so I am not able to identify the place in ABL code I am when trying to log using LegacyLogManager.
I guess in the end I need to write own functions to resolve this issue, but they will rely on the way code is converted and procedures are stuck in the current FWD version.

I am almost done with fixing existing tests, just circling around some FWD-OE differences like:

• There is a tests that checks all available Logging Entries - not sure if it makes sense as I guess reported values depend on OE configuration and licensing option, do they ?
  Expected values to OE 11.7:
  

  4GLMessages,4GLTrace,4GLTrans,Actional,ASK,DB.Connects,DB.Encryption,DS.Cursor,DS.QryInfo,DS.Performance,DynObjects.Class,DynObjects.DB,DynObjects.Other,DynObjects.UI,DynObjects.XML,FileID,IgnoredOps,MSASAdmin,MSASCRTInterposed,MSASSessions,MSASSignals,MSASSockets,MSASWebSocket,MSASDebugger,ProEvents.UI.Char,ProEvents.UI.Command,ProEvents.Other,QryInfo,SAX,Temp-Tables,TTStats,WSO
  

• different class structure in OpenEdge.Core compared to FWD - In OE there is no OpenEdge.Core.AbstractAssert.
  Thus 4GLTRACE tests that rely on class structure need to be rewritten I guess :) or maybe OpenEdge.Core.AbstractAssert should not be annotated with LegacyResource ?
  OE:
  

  [25/11/28@14:54:19.239+0100] P-009640 T-011916 3 4GL 4GLTRACE       Return from Equals [OpenEdge.Core.Assert]
  

  
  FWD:
  

  [25/11/28@13:18:59.804+0100] P-1025065 T-000184 3 4GL 4GLTRACE       Return from Equals [OpenEdge.Core.AbstractAssert]
  

• Object destructor needs type of referring variable type like in (I've solved that by passing object instead of reference whenever I could):
  

  [25/11/19@16:34:38.467+0100] P-008444 T-013192 2 4GL DYNOBJECTS     Deleted-by-GC  Progress.Lang.Object    Handle:1196 (testClassDynObj tests.log_manager.log_entry_types.TestDynObjectsEntry @ 116) tests.log_manager.support.LogEvent
  

• Mapping back method names from Java to 4GL does not always work (note case difference for TestSet4GLTrans)
  OE:
  

  [25/11/17@13:44:01.197+0100] P-010784 T-002516 3 4GL 4GLTRANS       BEGIN TRANS 4231 [TestSet4GLTrans tests.log_manager.TestLogEntryTypes @ 395]
  

  
  FWD:
  

  [25/11/20@18:46:52.788+0100] P-072763 T-000179 3 4GL 4GLTRANS        BEGIN TRANS 1 [testSet4Gltrans tests.log_manager.TestLogEntryTypes @ 1]
  

• Preconverted classes (like OpenEdge.Core.Assert) do not use TypeFactory so its not possible to intercept parameters:
  OE
  

  [25/11/28@14:54:19.239+0100] P-009640 T-011916 2 4GL 4GLTRACE       Invoke Equals in OpenEdge.Core.Assert "4gltrace:3 4gltrace:3" [TestSetValid4GLTrace - tests.log_manager.TestLogEntryTypes @ 280]
  

  
  FWD:
  

  [25/11/28@13:18:59.804+0100] P-1025065 T-000184 2 4GL 4GLTRACE       Invoke Equals in OpenEdge.Core.AbstractAssert [testSetValid4Gltrace - tests.log_manager.TestLogEntryTypes @ 1]
  

There is a tests that checks all available Logging Entries - not sure if it makes sense as I guess reported values depend on OE configuration and licensing option, do they ?

We should only report those logging entries which we support.

different class structure in OpenEdge.Core compared to FWD - In OE there is no OpenEdge.Core.AbstractAssert.

Constantin?

Mapping back method names from Java to 4GL does not always work (note case difference for TestSet4GLTrans)

Is this because we are reporting the Java method name instead of the legacy name?

Preconverted classes (like OpenEdge.Core.Assert) do not use TypeFactory so its not possible to intercept parameters:

Seems like a bug.

Greg Shah wrote:

different class structure in OpenEdge.Core compared to FWD - In OE there is no OpenEdge.Core.AbstractAssert.

Constantin?

Vladimir, this was added during the initial FWD Assert implementation; what was the reason for it? I can't find it in ADE code. If this is not something which exists in OE, then at the least we need to remove the @LegacyResource annotation.

Vladimir, this was added during the initial FWD Assert implementation; what was the reason for it?

com.goldencode.p2j.oo.core.AbstractAssert is an abstract base class for five final classes. Its descendants implement OE base classes, but the abstract class itself has no OE equivalent.

I can't find it in ADE code. If this is not something which exists in OE, then at the least we need to remove the @LegacyResource annotation.

Doing so will break 4GL class conversion:

     [java] Caused by: java.lang.NullPointerException: Cannot invoke "java.util.Map.get(Object)" because "com.goldencode.p2j.util.SourceNameMapper.j2pMap" is null
     [java]     at com.goldencode.p2j.util.SourceNameMapper.getLegacyClassName(SourceNameMapper.java:637)
     [java]     at com.goldencode.p2j.util.ObjectOps.legacyNameWorker(ObjectOps.java:4831)
     [java]     at com.goldencode.p2j.util.ObjectOps.registerClass(ObjectOps.java:4631)
     [java]     at com.goldencode.p2j.util.ObjectOps.<clinit>(ObjectOps.java:260)

Vladimir Tsichevski wrote:

Vladimir, this was added during the initial FWD Assert implementation; what was the reason for it?

com.goldencode.p2j.oo.core.AbstractAssert is an abstract base class for five final classes. Its descendants implement OE base classes, but the abstract class itself has no OE equivalent.

And its skeleton equivalent was added for the same reason?

I can't find it in ADE code. If this is not something which exists in OE, then at the least we need to remove the @LegacyResource annotation.

Doing so will break 4GL class conversion:

OK... then we need to fix that part, as at this time, FWD does not support mixed 4GL and pure-Java types in an hierarchy.

Tomasz Domin wrote:

I am almost done with fixing existing tests, just circling around some FWD-OE differences like:

• There is a tests that checks all available Logging Entries - not sure if it makes sense as I guess reported values depend on OE configuration and licensing option, do they ?
  Expected values to OE 11.7:
  [...]

I've changed the way the test work - instead of direct list comparison I am checking if given Log Entry Type is supported for FWD supported types only e.g.:

        Assert:IsIn('4GLMessages', hObj:entry-types-list, 'Entry Type is missing').

• different class structure in OpenEdge.Core compared to FWD - In OE there is no OpenEdge.Core.AbstractAssert.
  Thus 4GLTRACE tests that rely on class structure need to be rewritten I guess :) or maybe OpenEdge.Core.AbstractAssert should not be annotated with LegacyResource ?

I've resolved the issue by refactoring - I've moved equalsImpl from AbstractAssert to Assert, will do more refactoring if needed. Funny thing it was only used in a single sub-class.

• Mapping back method names from Java to 4GL does not always work (note case difference for TestSet4GLTrans)
  OE:
  [...]
  FWD:
  [...]

This is something I could not solve (for now) - in FWD names are in camelCase despite they start with upper case in 4GL code. Fortunately (or not) tests are doing case insensitive comparison.

• Preconverted classes (like OpenEdge.Core.Assert) do not use TypeFactory so its not possible to intercept parameters:

I've added references to TypeFactory in selected places of OpenEdge.Core.Assert native implementation.

All 61 tests are passing now.
Pushed up 3853a to revision 16287, I will rebase to trunk soon.

I will push updated tests to testcases project as soon as bzr update is done.

Tomasz Domin wrote:

I will push updated tests to testcases project as soon as bzr update is done.

I've pushed updated tests to tests/log_manager/ : Committed revision 1819.
The tests are updated for IE 11.7. If someone in GCD team having OE 11.6 could run them and report failures I'd appreciate it.

Based on provided customer logs (#10393, #9451) I've identified still to be implemented:
- complete set of 26 cases for WSADefault logging
- 3-4 missing cases for 4GLTRACE not covered by existing tests
- about 35-38 missing cases for DYNOBJECTS not covered by existing tests

I dont have sample logs for:
QryInfo - could be quite complicated from what I see above, as FWD persistence subsystem is completely difference
4GLMessages - some support is implemented
4GLTrans - some support is implemented for transactions and I've extended it to sub transactions
DB.Connects - some support is implemented
ASPlumbing - there is some pre #3853 support already in FWD
fileID - it is not on #3853-1 list, but its test file has been created as part of existing tests, thus it has low prio

QryInfo - could be quite complicated from what I see above, as FWD persistence subsystem is completely difference

We need a basic set of tests covering all core query types (e.g. FOR EACH, FIND, OPEN QUERY/GET...) and critical forms (single vs multi table, temp vs perm table, with where clause, with by clause...).

To a great degree, this is also just needed as a set of unit tests and this would be the "start" of those tests.

Alex/Eric: Please prepare a plan for how these tests (and #6855 in general) will move ahead.
Tomasz: For the purposes of logging, my thought here is that you could run these test sets (or other existings ones) to capture logs.

4GLMessages - some support is implemented
4GLTrans - some support is implemented for transactions and I've extended it to sub transactions
DB.Connects - some support is implemented
ASPlumbing - there is some pre #3853 support already in FWD

Please work with our team and customers to capture additional logs as needed.

Tomasz Domin wrote:

Based on provided customer logs (#10393, #9451) I've identified still to be implemented:
- 3-4 missing cases for 4GLTRACE not covered by existing tests

I've implemented all test cases I am aware of.

- about 35-38 missing cases for DYNOBJECTS not covered by existing tests

I've implemented all test cases I am aware of mostly in DYNOBJECTS.Class and DYNOBJECTS.UI, still missing cases for DYNOBJECTS.XML and DYNOBJECTS.OTHER and DYNOBJECTS.DB
These cases found in logs are not implemented as I dont know how to do them in FWD:

4GL DYNOBJECTS  Created        .NET Object
4GL DYNOBJECTS  Created-Ref    .NET Object
4GL DYNOBJECTS  Deleted        .NET Object

- complete set of 26 cases for WSADefault logging

Cases are simple, but the problem I have is how to run them as ABLUnit tests - WSA logging is server side logs - I'd need to start/stop app server and read it logs in ABLUnit, which I dont know how to do in an universal (OE/FWD) way.

I will switch to FWD implementation on implemented tests in meantime.

Tomasz Domin wrote:

I will switch to FWD implementation on implemented tests in meantime.

After cleaning and running test in FWD here are the results:

Test run finished after 2123 ms
[        23 containers found      ]
[         0 containers skipped    ]
[        23 containers started    ]
[         0 containers aborted    ]
[        23 containers successful ]
[         0 containers failed     ]
[        86 tests found           ]
[         0 tests skipped         ]
[        86 tests started         ]
[         0 tests aborted         ]
[        62 tests successful      ]
[        24 tests failed          ]

I am stuck a bit while still implementing 4GLTRACE.
The issue is double logging. There are more, but lets focus on two function call scenario:
- internal function call
- external procedure function call

They share a common part - entering BlockManager.functionBlock. I have to do logging there for internal function call as there is nowhere else to do it - in-procedure functions are called directly. The problem is I dont know what type of call it is at that stage and logging message is different depending on the way the function is called (Invoke, Func, SUPER, RUN).
My idea is to do all logging in BlockManager.functionBlock but put some contextual information in logging context, as I do for function input variables. Not sure if those should be some function call state or rather logging switches (like - do not log double Func log message).

Tomasz, there is BlockManager.checkJavaCall - the runtime can know via this that a 4GL function is called in the converted call via direct Java method call or via ControlFlowOps/InvokeConfig.

Constantin Asofiei wrote:

Tomasz, there is BlockManager.checkJavaCall - the runtime can know via this that a 4GL function is called in the converted call via direct Java method call or via ControlFlowOps/InvokeConfig.

That worked, thank you, are there maybe similar procedures to check if we are inside is initiated by PUBLISH ?

What about this: how to run application server ABLUnit tests - WSA logging is server side logs - I'd need to start/stop app server and read it logs in ABLUnit, which I dont know how to do in an universal (OE/FWD) way.

Greg Shah wrote:

For transaction id I am using TransactionManager.getTransactionId

I'm not sure about this. That API is matches the 4GL feature DBTASKID. Is that what the 4GL LOG-MANAGER will report?

No, it reporting some internal AVM Transaction ID, I hit that when tried to implement subtransaction logging, but I cant use TransactionManager.getTransactionId anymore.
I guess there is nothing like that in FWD, is there ?

Probably not since we dont have a need to lookup arbitrary transaction blocks based on unique identifiers. You can look in the TransactionManager and related classes at our transaction state. We can always add some kind of simple int value for this, but if we do it must be very efficient. I don't want to add overhead just for ensuring that logging is compatible.

Greg Shah wrote:

Probably not since we dont have a need to lookup arbitrary transaction blocks based on unique identifiers. You can look in the TransactionManager and related classes at our transaction state. We can always add some kind of simple int value for this, but if we do it must be very efficient. I don't want to add overhead just for ensuring that logging is compatible.

Thank you I've implemented an additional internal transaction id to track in case logging is enables as part of Block structure. That works.

While getting through DynOBjects I have a problem with accessing handle ID on resource destruction. Basically all objects are deleted by calling HandleOps.delete and then using Deletable interface. Legacy logs are producing logs like this:

[26/01/07@17:49:16.824+0100] P-000996 T-010856 2 4GL DYNOBJECTS     Created        PROCEDURE               Handle:1421 (testPendingProcedure tests.log_manager.log_entry_types.TestDynObjectsEntry @ 570) tests/log_manager/support/custom.p
[26/01/07@17:49:16.825+0100] P-000996 T-010856 2 4GL DYNOBJECTS     Delete Pending PROCEDURE               Handle:1421 (cleanup tests/log_manager/support/custom.p @ 9) tests/log_manager/support/custom.p
[26/01/07@17:49:16.825+0100] P-000996 T-010856 2 4GL DYNOBJECTS     Delete Pending PROCEDURE               Handle:1421 (cleanup tests/log_manager/support/custom.p @ 10) tests/log_manager/support/custom.p
[26/01/07@17:49:16.825+0100] P-000996 T-010856 2 4GL DYNOBJECTS     Deleted        PROCEDURE               Handle:1421 (testPendingProcedure tests.log_manager.log_entry_types.TestDynObjectsEntry @ 572) tests/log_manager/support/custom.p

I gave this example on purpose, as I have problem with getting Handle ID anywhere down the road of object deletion. I solved this temporarily by storing handle id in logging context, but that does not solve the problem of deferred procedure deletion which is called when popping the scope.

Is there a way to lookup handle or handle ID based on referred object ? From what I see only WrappedResource instances are stored in handle ? the problem is in most cases I have only a plain Object.

What resources are you deleting? In general, all resources inherit from HandleResource and this has an id() method. The exception are external programs and legacy OO instances: FWD in some places works directly with the instance of that external program (see ProcedureManager.delete, but usually these are wrapped via a WrappedResource and this reference held in the handle instance.

Constantin Asofiei wrote:

What resources are you deleting? In general, all resources inherit from HandleResource and this has an id() method. The exception are external programs and legacy OO instances: FWD in some places works directly with the instance of that external program (see ProcedureManager.delete, but usually these are wrapped via a WrappedResource and this reference held in the handle instance.

Until now - ExtProcWrapper, TempTableBuilder QueryWrapper,*DataModelObject*. Initially I've implemented logging in HandleOps.delete, but due to different scenarios I need to go deeper down to where the handle or even resource not available - but still I need to report original handle id.
Actually I've solved the issue I've reported above and next in the step will try to avoid storing handle in logging context at all.

Please also commit the changes to 3853a and rebase the branch; I'd like to take a look. Thanks.

There is different in the way OE and FWD are handling cleaning up after DELETE PROCEDURE THIS-PROCEDURE:

We have custom.p

PROCEDURE cleanup:
   DELETE PROCEDURE THIS-PROCEDURE. (9)
END PROCEDURE. (10)

And we have procedure call:

            RUN tests/log_manager/support/custom.p PERSISTENT SET hProc NO-ERROR.
            RUN cleanup IN hProc.

In OE that generates logs:

[26/01/07@17:49:16.825+0100] P-000996 T-010856 2 4GL DYNOBJECTS     Delete Pending PROCEDURE               Handle:1421 (cleanup tests/log_manager/support/custom.p @ 9) tests/log_manager/support/custom.p
[26/01/07@17:49:16.825+0100] P-000996 T-010856 2 4GL DYNOBJECTS     Delete Pending PROCEDURE               Handle:1421 (cleanup tests/log_manager/support/custom.p @ 10) tests/log_manager/support/custom.p
[26/01/07@17:49:16.825+0100] P-000996 T-010856 2 4GL DYNOBJECTS     Deleted        PROCEDURE               Handle:1421 (testPendingProcedure tests.log_manager.log_entry_types.TestDynObjectsEntry @ 572) tests/log_manager/support/custom.p

1. on DELETE PROCEDURE THIS-PROCEDURE.
2. on END PROCEDURE.
3. on returning control to calling procedure

1. on DELETE PROCEDURE THIS-PROCEDURE.
2. its somewhere in the middle of END PROCEDURE. and returning control in ProcedureManager.scopeFinished - when its possible to remove procedure from memory

It probably does not matter for runtime but it matters for logging, as I am unable to produce Delete Pending PROCEDURE message twice in FWD.
I will move on as I dont know what to do about it :)

Constantin Asofiei wrote:

Please also commit the changes to 3853a and rebase the branch; I'd like to take a look. Thanks.

Working changes are committed, note it needs cleaning, lots of cleaning, I was focusing on finding right places to generate logs before optimizations - first I need to know what data is needed in logs.
3853a is rebased to trunk/16410, Pushed up 3853a/16422.

One of test I've created is to check deleted object caching and reusing, but I guess FWD does not have pool of objects to recycle, and I wont be able to produce log like this, as I dont have required log triggering points in FWD:

[26/01/09@10:28:08.221+0100] P-014516 T-004948 3 4GL DYNOBJECTS     Reused         Progress.Lang.Object    Handle:0 (testCached tests.log_manager.log_entry_types.TestDynObjectsEntry @ 671) OpenEdge.Core.Collections.List
[26/01/09@10:28:08.221+0100] P-014516 T-004948 3 4GL DYNOBJECTS     Created        Progress.Lang.Object    Handle:1476 (testCached tests.log_manager.log_entry_types.TestDynObjectsEntry @ 671) OpenEdge.Core.Collections.List
[26/01/09@10:28:08.222+0100] P-014516 T-004948 2 4GL DYNOBJECTS     Deleted-by-GC  Progress.Lang.Object    Handle:1476 (testCached tests.log_manager.log_entry_types.TestDynObjectsEntry @ 673) OpenEdge.Core.Collections.List
[26/01/09@10:28:08.223+0100] P-014516 T-004948 3 4GL DYNOBJECTS     Cached         Progress.Lang.Object    Handle:1476 (testCached tests.log_manager.log_entry_types.TestDynObjectsEntry @ 673) OpenEdge.Core.Collections.List

What line do you mean? Deleted-by-GC?

Constantin Asofiei wrote:

What line do you mean? Deleted-by-GC?

That actually is implemented (with some context information storing).
I mean Reused and Cached.

Hm... is this related to the Progress.Lang.Object type associated with a Progress.Lang.Class instance (the equivalent of a java.lang.Class instance for i.e. java.lang.Object type in Java)?

It doesn't make sense to cache actual runtime instances; but it makes sense for OpenEdge to cache the types. In any case, FWD does not delete (ever) the Progress.Lang.Class instances so this will not be supported.

Tomasz Domin wrote:

Constantin Asofiei wrote:

What line do you mean? Deleted-by-GC?

That actually is implemented (with some context information storing).
I mean Reused and Cached.

I meant - Deleted-by-GC is the case of deleted when reference count is zero - I've just put logging there.

Constantin
There is some strange issue with warnings being converted to errors in ABLUnit tests.
I am generating a warning like this:

      ErrorManager.recordOrShowLogManagerWarning(11078, text, prefix);

The procedure:

block-level on error undo, throw.
class tests.log_manager.TestLoggingLevel:
    @Test.
    method public void TestSetInvalid ( ):
        define variable logLine as character no-undo.
        define variable logEvt  as LogEvent  no-undo.

        // try to set the attribute when no logfile set
        hObj:logging-level = ? no-error. // ErrorManager.recordOrShowLogManagerWarning(11078, text, prefix);
        support.test.AssertExt:Warning(11078, "~*~*Cannot set attribute LOGGING-LEVEL because log file name was not specified at startup. (11078)").
        ...
   end method.
end class.

But stubborn procedure mustManageLegacyError changes warning to error.

That does not happen for the same code in OE.

When running tests under Linux OPSYS is by default set to WIN32 due to tests being run in GUI mode (???) - that seems to be default testcases project configuration.

That produces false negative for OS dependent tests like text file length comparison (like @tests.log_manager.TestClearLog.testtValid)

Constantin
I've pushed 3853a revision 16443 and testcases revision 1827.
Please do mid-work review - I need some suggestions about further optimization.

I will work in parallel on the WSADefault logging.

How to run tests - you need to be in testcases project root and run:
./deploy/client/run-tests.sh --reports-dir=/home/${USER}/projects/testcases --select-package=com.goldencode.testcases.tests.log_manager

zfileset.txt

N ./tests/log_manager/ (*.[pPwW]|*.cls)
N ./tests/log_manager/log_entry_types/ (*.[pPwW]|*.cls)
N ./tests/log_manager/support/ (*.[pPwW]|*.cls)

• this may be something generic, but for example: in ConnectionManager, LegacyLogOps.logMgr().writeMessage is being used. This in turn computes the message and maybe some other state, and in turn only when it reaches LegacyLogManagerImpl will decide that this doesn't have to be logged; this work being done before we decide that the log type is not needed is expensive, especially in high-executed code like ControlFlowOps or QueryWrapper. What I mean here: I think we need to protect this with code something like if (logManager.isLoggingEnabled() && logManager.isLogEntryTypeEnabled(DB_Connects)). This would apply to all cases.
• for resource-level logging (like QueryWrapper or TempTableBuilder - can we use an LoggingResource interface with an API which gets all required parameters, with a default (no-op?) implementation in HandleResource and let the resource call it with the proper arguments? The same can be applied to the code in HandleOps.delete
• there is an unused import import org.apache.commons.lang3.tuple.*; in many files
• some files are missing history and there are some javadoc issues in ObjectOps.decrement, LegacyLogManagerImpl.getLoggingLevel/switchLogFile
• APIs from LegacyLogOps like setInConstructor which are used in a bracket (set to true, execute, then false) need to do a backup/restore: you can have nested constructors called. So, code like this applies to all flags added to LegacyLogOps which are set to true and then false, and needs to be reworked like this:
  

  boolean old = LegacyLogOps.isInConstructor();
  try
  {
     LegacyLogOps.setInConstructor(true);
     // do work
  }
  finally
  {
     LegacyLogOps.setInConstructor(old);
  }
  

• this is a performance concern: calling LegacyLogOps.logMgr() requires a context-local resolution (which is expensive). We have a pattern where we save in existing WorkArea instances or even at the actual resource a 'helper' which has direct access to that context-local code. See how TransactionManager$TransactionHelper and getTransactionHelper is being used as an example.
• are there other resources for which logging was not added? Or otherwise some notes what is left for this task?

Thank you :)

Constantin Asofiei wrote:

Tomasz, these are some notes about the current implementation:

• this may be something generic, but for example: in ConnectionManager, LegacyLogOps.logMgr().writeMessage is being used. This in turn computes the message and maybe some other state, and in turn only when it reaches LegacyLogManagerImpl will decide that this doesn't have to be logged; this work being done before we decide that the log type is not needed is expensive, especially in high-executed code like ControlFlowOps or QueryWrapper. What I mean here: I think we need to protect this with code something like if (logManager.isLoggingEnabled() && logManager.isLogEntryTypeEnabled(DB_Connects)). This would apply to all cases.

I see, there was no API to do that when I was writing ConnectionManager logging.

• for resource-level logging (like QueryWrapper or TempTableBuilder - can we use an LoggingResource interface with an API which gets all required parameters, with a default (no-op?) implementation in HandleResource and let the resource call it with the proper arguments? The same can be applied to the code in HandleOps.delete

I was planning to move "delete" for those down the code the same way I had to do with Procedure.delete, I will check LoggingResource interface

• there is an unused import import org.apache.commons.lang3.tuple.*; in many files

Thats leftover, to be removed.

• some files are missing history and there are some javadoc issues in ObjectOps.decrement, LegacyLogManagerImpl.getLoggingLevel/switchLogFile

Thanks, will fix.

• APIs from LegacyLogOps like setInConstructor which are used in a bracket (set to true, execute, then false) need to do a backup/restore: you can have nested constructors called. So, code like this applies to all flags added to LegacyLogOps which are set to true and then false, and needs to be reworked like this:
  [...]

Sure, Will fix that.

• this is a performance concern: calling LegacyLogOps.logMgr() requires a context-local resolution (which is expensive). We have a pattern where we save in existing WorkArea instances or even at the actual resource a 'helper' which has direct access to that context-local code. See how TransactionManager$TransactionHelper and getTransactionHelper is being used as an example.

But there are so many different work areas ... not sure if that pays off. But I got the idea.

• are there other resources for which logging was not added? Or otherwise some notes what is left for this task?

All GUI resources are not handled:

   ├─ tests.log_manager.log_entry_types.TestDynObjectsUI ✔
   │  ├─ testWindow ✘ Expected: 2 but was: 1
   │  ├─ testButton ✘ Expected: 2 but was: 1
   │  ├─ testRectangle ✘ Expected: 2 but was: 1
   │  ├─ testText ✘ Expected: 2 but was: 1
   │  ├─ testMenu ✘ Expected: 2 but was: 1
   │  ├─ testSubMenu ✘ Expected: 2 but was: 1
   │  └─ testMenuItem ✘ Expected: 2 but was: 1

Constantin Asofiei wrote:

Tomasz, these are some notes about the current implementation:

I think I've done that all (more or less).
Pushed up to revision 16448.

I've found a glitch and Pushed up to revision 16449.

I've run regression tests with 3853a and it fails the same way as trunk/16429 it is based on - so its presumed tests are passing.

Tomasz Domin wrote:

Based on provided customer logs (#10393, #9451) I've identified still to be implemented:
- complete set of 26 cases for WSADefault logging

This was not implemented.

The cases (one per line) are like below (anonymized) - I dont think it would be implemented all messages, as they are based on tomcat, not jetty.

[22/11/01@04:57:58.451+0000]    P-011317    T-main    3    wsa1    WSA    Starting WSA adapter wsa1, version 10.2B, ID XXXXXXXX20d5b1ad:343f3af0:184318da88f:-7fff (10620)          
[22/11/01@04:57:58.652+0000]    P-011317    T-main    3    wsa1    WSA    Loading the Web Service applications registry             
[22/11/01@04:57:58.743+0000]    P-011317    T-main    3    wsa1    WSA    Loaded XML Schema: /usr/xxx/properties/schemas/wsxxxxxx.xsd               
[22/11/01@04:57:59.826+0000]    P-011317    T-main    3    wsa1    WSA    Initialization parameter: instanceName value: wsa1 (10965)             
[22/11/01@12:29:01.596+0000]    P-011317    T-http-8080-1    3    wsa1    WSA    New Request: ID=0 (10927)               
[23/02/09@10:11:32.577+0000]    P-000000    T-ContainerBackgroundProcessor[StandardEngine[Catalina]]    1    wsa1    ----------------    XML exception parsing file /opt/tomcat/webapps/xxx//wsa1/default.props: /opt/tomcat/webapps/xxx/wsa1/default.props (No such file or directory) (10734)       
[23/02/09@10:11:32.577+0000]    P-000000    T-ContainerBackgroundProcessor[StandardEngine[Catalina]]    1    wsa1    ----------------    Error parsing /opt/tomcat/webapps/xxx//wsa1/default.props. Using cached copy of runtime properties and disabling service. (10755)      
[23/03/09@15:54:24.038+0000]    P-028883    T-http-8443-4    1    wsa1    ----------------    Error in POST request: null              
[23/02/09@16:40:42.427+0000]    P-004175    T-http-8080-2    3    wsa1    Admin-Provider    Creating Application Runtime Property file: /opt/tomcat/webapps/wsa//wsa1/xxx.props             
[22/11/01@04:57:59.423+0000]    P-011317    T-main    3    wsa1    Admin-Provider    Creating pool manager: XXXXXXX               
[23/02/09@16:40:42.254+0000]    P-004175    T-http-8080-2    3    wsa1    Admin-Provider    Creating WSAD file: /opt/tomcat/webapps/wsa//wsa1/xxx.wsad               
[23/02/09@16:40:42.291+0000]    P-004175    T-http-8080-2    3    wsa1    Admin-Provider    Creating WSDL file: /opt/tomcat/webapps/wsa//wsa1/xxx.wsdl               
[23/02/09@16:40:34.884+0000]    P-004175    T-http-8080-1    2    wsa1    Admin-Provider    Disabling Web Service application xxx (10875)             
[23/02/09@16:40:48.394+0000]    P-004175    T-http-8080-3    2    wsa1    Admin-Provider    Enabling Web Service application xxx (10874)             
[22/11/01@04:57:59.405+0000]    P-011317    T-main    3    wsa1    Admin-Provider    Generating deployment descriptors                
[22/11/01@04:57:59.781+0000]    P-011317    T-main    3    wsa1    Admin-Provider    Initializing Application: default                
[22/11/01@04:57:59.795+0000]    P-011317    T-main    3    wsa1    Admin-Provider    Loaded application runtime properties: /opt/tomcat/webapps/wsa//xxx/default.props              
[22/11/03@05:01:32.925+0000]    P-007315    T-main    3    wsa1    Admin-Provider    Loading application descriptor: /opt/tomcat/webapps/wsa//xxx/xxx.wsad               
[23/02/09@10:11:32.577+0000]    P-000000    T-ContainerBackgroundProcessor[StandardEngine[Catalina]]    3    wsa1    Admin-Provider    Saving runtime properties for application default to disk.           
[23/02/09@16:40:42.242+0000]    P-004175    T-http-8080-2    2    wsa1    Admin-Provider    Updating Web Service application xxx (10872)             
[23/02/09@17:24:33.960+0000]    P-030496    T-http-8443-1    4    wsa1    Message-Debug    POST request received from client anonymous at address xx.xx.xx.xx (10963)         
[23/02/09@17:24:33.972+0000]    P-030496    T-http-8443-1    4    wsa1    Message-Debug    Raw SOAP request:                
[23/02/09@17:24:34.299+0000]    P-030496    T-http-8443-1    4    wsa1    Message-Debug    Raw SOAP response:                
[23/02/09@17:24:34.299+0000]    P-030496    T-http-8443-1    4    wsa1    Message-Debug    (10960) 

LOG-MANAGER Tests is where we document the details of our testcases for exploring the logging features. (I just noticed we don't mention that above.)

Status Update from Tomasz

1. There was already some support for:

4GLMessages
ASPlumbing

2. I've implemented tests for everything I had logs for with exception for WSADefault. So following LoggingEntryType have been implemented:

4GLTrans
4GLTrace
DB.Connects
DynObjects.Class
DynObjects.Buffers
DynObjects.Queries
DynObjects.Temptables
DynObjects.Procedures
DynObjects.Class
DynObjects.WidgetPool
DynObjects.* as a wildcard

3. Not implemented:

DynObjects.UI - see #3853-144 for a list of cases - each line is a single case to be implemented somewhere in app server.
WSADefault
QryInfo
fileID

4. How to run tests:

You need to be in testcases root project root directory, otherwise some tests that output files to current directory may fail.

You need to use deploy/client/run-tests.sh script, it was commited into testcases project in commit 1827
I only ran the tests in OE using Developer Studio, I dont think I've ever used ant for that, but that should be possible the same way as for other test cases.

Tests are using a standard testcases project database.

Running Single tests class:

./deploy/client/run-tests.sh --reports-dir=/home/tjd/projects/testcases --select-class=com.goldencode.testcases.tests.log_manager.log_entry_types.TestDynObjectsEntry

or

./deploy/client/run-tests.sh --reports-dir=/home/tjd/projects/testcases --select-class=com.goldencode.testcases.tests.log_manager.TestLoggingLevel

Running all tests:

./deploy/client/run-tests.sh --reports-dir=/home/tjd/projects/testcases --select-package=com.goldencode.testcases.tests.log_manager

5. The current results are:

Test run finished after 2494 ms
[        23 containers found      ]
[         0 containers skipped    ]
[        23 containers started    ]
[         0 containers aborted    ]
[        23 containers successful ]
[         0 containers failed     ]
[        86 tests found           ]
[         0 tests skipped         ]
[        86 tests started         ]
[         0 tests aborted         ]
[        75 tests successful      ]
[        11 tests failed          ]

List of tests:

Note that not all tests were written by me - the structure of the test suite and most tests were written by Marian and the Acorn team - nevertheless I've added several new testcases to existing tests.

└─ FWD Test ✔
   ├─ tests.log_manager.TestWriteMessage ✔ - test of log-manager:write-message
   │  ├─ testWriteNoLogOpen ✔ - test writing in case log file is not open
   │  ├─ testFileSizeAfterWrite ✔ - test if log file changes after write
   │  ├─ testWrite ✔ - test is writing to log file works
   │  └─ testWriteWithSubsys ✔ - test is writing to log file works with a custom subsys set up
   ├─ tests.log_manager.TestType ✔ - tests for log-manager:test-type attribute
   │  ├─ testGet ✔ - get the attibute and check if its a pseudo-widget
   │  └─ testSetInvalid ✔ - try to set the attribute to invalid value and check error codes generated
   ├─ tests.log_manager.log_entry_types.Test4glMessagesEntry ✔ - test for different log-manager:log-entry-types=4glmessages log levels
   │  ├─ testLogLevels0To1 ✔ - Check behaviour of log levels 0-1
   │  └─ testLogLevels2To4 ✔ - Check behaviour of log levels 2-4
   ├─ tests.log_manager.log_entry_types.Test4glTraceEntry ✔ test for different cases for log-manager:log-entry-types=4gltrace log levels
   │  ├─ testLogLevels0To1 ✔ - Check behaviour of log levels 0-1 for no-op
   │  ├─ testInstantiateObject ✔ - check messages when instantiating new object: dummy = new LogEvent().
   │  ├─ testInvokeMethod ✔ - check messages when invoking objects method: dummyMethod("param1", 2).
   │  ├─ testCallProc ✔ - check messages when calling procedure: run tests/log_manager/support/custom.p.
   │  ├─ testReturn ✔- check messages when returning from precedure or method
   │  ├─ testSuper ✔ - check messages generated on calling SUPER for a procedure after hChild: ADD-SUPER-PROCEDURE(hParent)
   │  ├─ testFunc ✔ - check messages for calling a dynamic function: DYNAMIC-FUNCTION("func_top" IN hCustom) NO-ERROR.
   │  └─ testSubscribedEvents ✔ - check messages generated on SUBSCRIBE, PUBLISH, UNSUBSCRIBE cycle - to be removed as this is part of the next test
   ├─ tests.log_manager.log_entry_types.Test4glTraceEventEntry ✔ test for different cases for log-manager:log-entry-types=4gltrace log levels and subscriptions
   │  ├─ testLogLevels0To1 ✔ - Check behaviour of log levels 0-1 for no-op
   │  └─ testSubscribedEvents ✔ - check messages generated on SUBSCRIBE, PUBLISH, UNSUBSCRIBE cycle
   ├─ tests.log_manager.log_entry_types.Test4glTransEntry ✔ test for different cases for log-manager:log-entry-types=4gltrans log levels
   │  ├─ testLogLevels0To1 ✔ - Check behaviour of log levels 0-1 for no-op
   │  ├─ testNormalTrans ✔ - check logging for single level transaction with commit
   │  ├─ testUndoTrans ✔ - check logging for single level transaction with undo
   │  ├─ testNormalSubTrans ✔ - check logging for transaction and subtransaction with commit
   │  └─ testNormalSubSubTrans ✔ - check logging for transaction and two subtransactions with commit
   ├─ tests.log_manager.log_entry_types.TestDbConnectsEntry ✔ test for different cases for log-manager:log-entry-types=db.connects log levels
   │  ├─ testLogLevels0To1 ✔ - Check behaviour of log levels 0-1 for no-op
   │  ├─ testLogLevels2To3 ✔ - check for standard db.connects logging level 2-3
   │  └─ testLogLevel4 ✔ - check for additional messages for log level 4
   ├─ tests.log_manager.log_entry_types.TestDynObjectsEntry ✔ - test for different cases for log-manager:log-entry-types=dynobjects Class, DB, Other, UI, XML log levels
   │  ├─ testLogLevels0To1 ✔ - Check behaviour of log levels 0-1 for no-op
   │  ├─ testClassDynObj ✔ - check messages for dynobjects.Class
   │  ├─ testDbDynObj ✔ - check messages for dynobjects.Db - not implemented
   │  ├─ testUiDynObj ✔ - check messages for dynobjects.Ui - not implemented - there a separate class for that TestDynObjectsUI
   │  ├─ testXmlDynObj ✔ - check messages for dynobjects.Xml - not implemented
   │  ├─ testOtherDynObj ✔ check messages for dynobjects.Other - not implemented
   │  ├─ testConstructorDeleted ✔ - DYNAMIC-NEW className() and DELETE for dynobjects.Class
   │  ├─ testProcedure ✔ - RUN tests/log_manager/support/custom.p PERSISTENT SET hProc NO-ERROR. for DynObjects.Procedures
   │  ├─ testTempTable ✔ - CREATE TEMP-TABLE hTable for DynObjects.Temptables
   │  ├─ testQuery ✔ - CREATE QUERY hQuery for DynObjects.Queries
   │  ├─ testBuffer ✔ - CREATE BUFFER hBuffer for DynObjects.Buffers
   │  ├─ testPendingProcedure ✘ Expected: TRUE but was: no  - pending procedure case for DynObjects.Procedures, see #3853-127
   │  ├─ testCached ✘ Expected: TRUE but was: no - DynObjects.Class special case, see #3853-132
   │  ├─ testUnnamedPool ✔ - CREATE WIDGET-POOL for DynObjects.WidgetPool
   │  └─ testNamedPool ✔ - CREATE WIDGET-POOL "test123" for DynObjects.WidgetPool
   ├─ tests.log_manager.log_entry_types.TestDynObjectsUI ✔ - not implemented yet - logging for different DynObjects.Widgets
   │  ├─ testWindow ✘ Expected: 2 but was: 1 - CREATE WINDOW hWindow logging
   │  ├─ testButton ✘ Expected: 2 but was: 1 - CREATE BUTTON hButton logging
   │  ├─ testRectangle ✘ Expected: 2 but was: 1 - CREATE RECTANGLE hRectangle logging
   │  ├─ testText ✘ Expected: 2 but was: 1 - CREATE TEXT hText.
   │  ├─ testMenu ✘ Expected: 2 but was: 1 - CREATE MENU hMenu.
   │  ├─ testSubMenu ✘ Expected: 2 but was: 1 - CREATE SUB-MENU hMenu.
   │  └─ testMenuItem ✘ Expected: 2 but was: 1 - CREATE MENU-ITEM hMenu.
   ├─ tests.log_manager.log_entry_types.TestFileIdsEntry ✔ - not implemented
   │  └─ testLogLevels0To1 ✔
   ├─ tests.log_manager.log_entry_types.TestQryInfoEntry ✔ - not implemented
   │  └─ testLogLevels0To1 ✔
   ├─ tests.log_manager.TestClearLog ✔ - log-manager:clear-log tests
   │  ├─ testInvalid ✔ - try to clear logs which is not configured
   │  └─ testValid ✘ Expected: 168 but was: 166 - check log files generation after log fiel reset with clear-log - fails due to bad OS detection
   ├─ tests.log_manager.TestCloseLog ✔ - log-manager:logfile-name setting
   │  └─ testSetValid ✔ - set valid parametrs and check generated file
   ├─ tests.log_manager.TestDefaults ✔ - test default values of attributes
   │  ├─ testDefaultEntryTypesList ✔ - check defaults for log-manager:entry-types-list
   │  ├─ testDefaultHandle ✔ - check defaults for log-manager:handle
   │  ├─ testDefaultInstantiatingProcedure ✔ - check defaults for log-manager:instantiating-procedure
   │  ├─ testDefaultLogEntryTypes ✔ - check defaults for log-manager:log-entry-types
   │  ├─ testDefaultName ✔ - check defaults for log-manager:logfile-name
   │  ├─ testDefaultLoggingLevel ✔ - check defaults for log-manager:logging-level
   │  ├─ testDefaultLogThreshold ✔ - check defaults for log-manager:log-threshold
   │  ├─ testDefaultNumLogFiles ✔ - check defaults for log-manager:num-log-files
   │  └─ testDefaultType ✔ - check defaults for log-manager:hObj:type
   ├─ tests.log_manager.TestEntryTypesList ✔ - test manipulating of log-manager:entry-types-list
   │  ├─ testGet ✔ - test reading log-manager:entry-types-list
   │  └─ testSetInvalid ✔ - test setting log-manager:entry-types-list to invalid value and related errors
   ├─ tests.log_manager.TestHandle ✔ - tests manipulating of log-manager:handle
   │  ├─ testGet ✔ - test reading log-manager:handle
   │  └─ testSetInvalid ✔ - test setting log-manager:handle to invalid value and related errors
   ├─ tests.log_manager.TestLogEntryTypes ✔ - tests manipulating log-manager:log-entry-types attribute
   │  ├─ testGet ✔ - get value of log-manager:log-entry-types
   │  ├─ testSetInvalid ✔ - test setting log-manager:log-entry-types to invalid/non-existing value, check expected errors
   │  ├─ testSetValid ✔ - test setting log-manager:log-entry-types to a valid value,
   │  ├─ testSet4Glmessages ✔ - test setting log-manager:log-entry-types to 4glmessages
   │  ├─ testSetValid4Gltrace ✔ - test setting log-manager:log-entry-types to 4gltrace
   │  ├─ testSet4Gltrans ✔ - test setting log-manager:log-entry-types to 4gltrans
   │  ├─ testSetDbconnects ✔ - test setting log-manager:log-entry-types to db.connects
   │  ├─ testSetDynobjects ✔ - test setting log-manager:log-entry-types to DynObjects.Class DynObjects.DB DynObjects.Other DynObjects.UI DynObjects.XML
   │  ├─ testSetFileid ✔ - test setting log-manager:log-entry-types to db.connects fileid
   │  └─ testSetQryInfo ✔ - test setting log-manager:log-entry-types to qryinfo
   ├─ tests.log_manager.TestLogfileName ✔ - tests manipulating log-manager:log-file-name attribute
   │  ├─ testGet ✔ - get value of log-manager:log-file-name
   │  └─ testSetValidAndInvalid ✔ - test setting log-manager:log-file-name to valid or invalid/non-existing value, check expected errors
   ├─ tests.log_manager.TestLoggingLevel ✔ - tests manipulating log-manager:logging-level attribute
   │  ├─ testGet ✔ - get value of log-manager:logging-level
   │  ├─ testSetInvalid ✘ Statement expected to raise warning but error was thrown. - test setting log-manager:logging-level to invalid/non-existing value, check warnings/errors it should work I guess
   │  └─ testSetValid ✔ - test setting log-manager:logging-level to valid value
   ├─ tests.log_manager.TestLogThreshold ✔ - tests manipulating log-manager:log-threshold attribute
   │  ├─ testGet ✔ get value of log-manager:log-threshold
   │  └─ testSetInvalid ✔ - test setting log-manager:log-threshold to invalid/non-existing value, check warnings/errors
   ├─ tests.log_manager.TestNumLogFiles ✔ - tests manipulating log-manager:num-log-files attribute
   │  ├─ testGet ✔ - get value of log-manager:num-log-files
   │  └─ testSetInvalid ✔ - test setting log-manager:num-log-files to invalid/non-existing value, check warnings/errors
   └─ tests/log_manager/TestInstantiatingProcedure.p ✔ - tests manipulating log-manager:instantiating-procedure attribute
      └─ testInstantiatingProcedure ✔ - test reading and setting log-manager:instantiating-procedure attribute