Ask Reuben

GAS Logs

Where are the GAS logs?

What is in the GAS logs?

How do I interpret a GAS log?

When an issue is raised with a Genero application running via Genero Application Server, as well as the standard questions from us you might have heard before such as …

can you reproduce in a small example ?
does it occur with the latest maintenance release ?
does the issue occur without your customisation ?
does the issue without your .4st stylesheet ?
etc

… we may ask the question…

what do the logs say?
or have you looked in the logs?
or can you please send us the logs?

and sometimes the reply is …

where are the logs?
or I have not even looked in the logs !!!

Where are the GAS logs?

The location of the GAS logs is configurable from within your GAS configuration file. The default location is in the GAS Application data directory and that will vary by OS …

On Linux/Unix/OSX: $FGLASDIR/appdata/log
On Windows: C:\Program Data\Fourjs\gas\gas_version\log

Within this directory, a directory is created for each dispatcher (e.g. httpdispatch, fastcgidispatch) and within that directory there is a directory created for each day in the format YYYYMMDD. So if you installed GAS onto the default directory on a Linux server, used httpdispatch, for the GAS logs on 1st January 2021 you would find them in /opt/fourjs/gas/appdata/log/httpdispatch/20210101

For production, you typically want to move the location of the logs to somewhere you have sufficient disk space.

It is important that if you are running multiple dispatchers on the one server that you configure the logs to be placed in a separate directory for each dispatcher instance, see the documentation on configuring multiple dispatchers.

What can you configure with GAS logs?

The LOG element in the GAS configuration file allows you to configure specific details about the GAS log files. These include …

OUTPUT which allows you to change the location as well as providing a means to write the logs to the console.
FORMAT allows you to configure how each line is output in the log.
CATEGORIES_FILTER allows you to indicate what information is output to the logs.
RAW_DATA allows you to limit the size of a line in the log.

As these are in the main configuration file, if you want to make a change to any of these this will require a stop and start of the dispatcher in order for the change to come into effect.

I find it is very rare to require a change, you will typically make any adjustments to the default when you first configure your system.

To change the location of the GAS logs, you might make an adjustment in the OUTPUT node but you should also note that the default value is a resource “$(res.log.output.path)” which in turn is defined via other resources as “$(res.appdata.path)/log” which in turn is defined on Linux/Unix/OSX “$(res.path.as)/appdata/log” or on Windows “#!APPDATADIR!#\gas\\log”. So rather than changing the value explicitly in OUTPUT you could change the location by changing the res.appdata.path resource entry or override it using the -E command line argument for the dispatcher.

With the FORMAT entry it is rare to make a change. The most common I have seen is to add the “category” value near the beginning as that helps you to understand what the various values in the CATEGORIES_FILTER write to the log.

The CATEGORIES_FILTER is the most common one to change depending upon what detail you want to see in the logs. There is a value DEBUG that your support contact may ask to add. The most useful value in the Table is the “ALL” value, I tend to simply use that when analysing to get the maximum output rather than worrying about what categories to use. The key thing to note when using “ALL” is that you don’t have to delete the existing entries, you can change the default “GAS ACCESS PROCESS DEPRECATED ERROR WARNING” to “ALL GAS ACCESS PROCESS DEPRECATED ERROR WARNING”, you don’t have to delete the other values and just leave “ALL” and then worry about what values you had when you decide not to use ALL anymore.

The last entry RAW_DATA is typically used if you change the CATEGORIES_FILTER to ALL or include HTTP as your lines in the log may include hundreds of characters of data and make the logs hard to read if there is wrapping. Typically you are not interested in the actual data but what time the various events occurred and what the status was.

What files are written to the log directory?

You will see three types of log files.

Dispatcher as the name suggests is a log file for the dispatcher, it will have a name like httpdispatch.log, fastcgidispatch.log

Proxy as the name suggests is a log file for the proxy processes. For web and desktop applications, each session will generate a proxy log file that is named uaproxy-sessionid.log For web services, each web service will generate a proxy log file that is named gwsproxy_group_app.log.

The VM logs capture the stdout and stderr of the running Genero applications. For desktop and web applications they are written to vm-sessionid.log. Note that two or more programs can write to the same vm log for a Genero application as a vm log is created per session. Child programs started with RUN are considered part of the same session. For Web Services as the gwsproxy can spawn multiple instances of the same application as per the Services Pool configuration, these are written to files named vm-group–app–number.log. So for the Calculator demo, the first program launched will write to vm-demo-Calculator-0.log, if a second program ls launched when demand gets high its output will be written to vm-demo-Calculator-1.log

When analysing an issue, you will typically be looking at the dispatcher log file and the proxy and vm log files for a session or a web service.

Tips for reading dispatcher log files.

When you see …

#Version: 1.0
#Date: yyyy/mm.dd hh:mm:ss.ffffff

… this tells you that the dispatcher has restarted at this time

If the lines above this #Version are …

hh:mm:ss.fffff s.fffff [times.c:354] 19021 340463040 - "Resource usage" (Incremental) Real: 1.013640, User: 0.003393, Sys: 0.002163, CPU (total: 0.54 %), (user : 0.33 %), (sys : 0.21 %),
hh:mm:ss.fffff s.fffff [times.c:354] 19021 340463040 - "Resource usage" (Since startup) Real: 21.048638, User: 0.023272, Sys: 0.033306, CPU (total: 0.26 %), (user : 0.11 %), (sys : 0.15 %),

… this tells you that the dispatcher was shutdown in a controlled manner as this resource usage is the last thing written to the log when a dispatcher shuts down.

The second thing the dispatcher writes to the log is the various ulimits that are in place for this process e.g.

#Ulimits:
#   core file size     : 0 (unlimited)
#   data seg size      : unlimited (unlimited)
#   file size          : unlimited (unlimited)
#   max memory size    : unlimited (unlimited)
#   open files         : 256 (unlimited)
#   stack size         : 8388608 (67104768)
#   cpu time           : unlimited (unlimited)
#   max user processes : 2784 (4176)
#   virtual memory     : unlimited (unlimited)

… this very quickly enables us to see if these are sufficient. In the above example, the open files value maybe a bit small.

Once an application is running, there should be many request/response pairs e.g.

hh:mm:ss.ffffff "Incoming request" /ua/sua/b317ed94c5167bab7be54ea8ca7a8ed5?appId=0&pageId=2
hh:mm:ss.ffffff "Response sent" 127.0.0.1 - [Day, dd Mmm yyyy hh:mm:ss GMT] "POST /ua/sua/b317ed94c5167bab7be54ea8ca7a8ed5 HTTP/1.1" 200 296 "http://localhost:6394/ua/r/gwc-demo" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/93.0.4577.63 Safari/537.36" query string: appId=0&pageId=2

… The 200 is the HTTP success response.

The big long hexadecimal string is the session-id that corresponds to the name of the session. A tip is to grep for this string in the dispatcher and then you only see the communication relating to that particular session e.g. grep “b317ed94c5167bab7be54ea8ca7a8ed5″ *dispatch.log
The appId relates to additional programs launched via RUN etc.
The pageId relates to the interaction coming via the AUI protocol and increments on each interaction.
If you compare the date/time stamp to entries in your web server log, make sure to synchronise the clocks or be aware of what the difference is between your web server timestamps and application server timestamps.

Tips for reading proxy log files

As with the dispatcher, the starttime, ulimits output and the resource entry can tell you when the proxy process was started, what O/S resources it could use, and if it exited correctly.
For GAS web applications, the session-id is incorporated in the proxy and VM log filename. The session-id is a 32 character hexadecimal string that is unique to a session. Any additional Genero applications started by this program will have the same session id, so be aware that the proxy and VM log files can contain information relating to more than one fglrun process.
The beginning of the proxy log can contain information such as various GAS configuration and environment variables that are injected and used by the launched application. These can be used to confirm that the values in the configuration file are as you expect. e.g. the value of USER_AGENT from the configuration file …

hh:mm:ss.ffffff s.ffffff [log.c:1571] 22424 0 - "Info-Environment" FGL_VMPROXY_USER_AGENT=300

You can see what program was started and if it successfully started e.g. in this case the demo program …

hh:mm:ss.492741 0.005085 [fjs_process.c:188] 22424 0 REQID=12;HTTP=0 "Start process" Directory: /Applications/fourjs/fgl/4.00.03/demo, Command line: "/Applications/fourjs/fgl/4.00.03/bin/fglrun" demo.42m
hh:mm:ss.493874 0.006222 [fjs_process.c:357] 22424 0 REQID=12;HTTP=0 "Start process" PID=22425 CommandLine="/Applications/fourjs/fgl/4.00.03/bin/fglrun" demo.42m
hh:mm:ss.494770 0.007114 [fjs_process.c:365] 22424 0 REQID=12;HTTP=0 "Process was started" PID=22425 CommandLine="/Applications/fourjs/fgl/4.00.03/bin/fglrun" demo.42m
hh:mm:ss.516478 0.028823 [uaproxy.c:770] 22424 0 - "VM Connection" SOCKET=e180de00, VM=0
hh:mm:ss.516711 0.029055 [gasrequest.c:966] 22424 0 REQID=12;HTTP=0;VM=0 "Receiving VM" meta Connection {{encoding "UTF-8"} {protocolVersion "102"} {interfaceVersion "110"} {runtimeVersion "4.00.03-2525"} {compression "none"} {encapsulation "1"} {filetransfer "1"} {filetransferVersion "2"} {filetransferFC "1"} {frontEndID "{ce136983-7d9f-1312-88f6-98cd49458575}"} {procId "Reubens-MacBook-Pro-5.local:22425"} {programName "demo"}}\n

… the timestamps can tell you how long the program took to start and respond, in this case 0.02 of a second.

You will then see the communication that shows the proxy receiving the action from the front-end, sending the AUI changes to the running program, receiving the changes to the AUI Tree from the running program, sending them to the front-end client e.g. you may recognise this info from a GDC log file for increasing the size of the tree and sending an additional row of data.

14:33:38.913547 0.425893 [gasrequest.c:1829] 22424 0 REQID=20;HTTP=2 "Receiving UA" POST /ua/sua/5b45685db1ced62611c8aaaacc5a467a?ConnectorURI=&appId=0&pageId=2 HTTP/1.1\r\nContent-Type: text/plain;charset=UTF-8\r\nX-FourJs-Client-Features: prompt\r\nUser-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/93.0.4577.63 Safari/537.36\r\nsec-ch-ua: "Google Chrome";v="93", " Not;A Brand";v="99", "Chromium";v="93"\r\nAccept: */*\r\nSec-Fetch-Dest: empty\r\nOrigin: http://localhost:6394\r\nsec-ch-ua-platform: "macOS"\r\nReferer: http://localhost:6394/ua/r/gwc-demo\r\nAccept-Language: en-GB,en-US;q=0.9,en;q=0.8\r\nAccept-Encoding: gzip, deflate, br\r\nSec-Fetch-Mode: cors\r\nSec-Fetch-Site: same-origin\r\nX-FourJs-Client: GBC/4.00.03-202108311804\r\nHost: localhost:6394\r\nContent-Length: 80\r\nConnection: keep-alive\r\nCookie: lang=en-US; Genero-SID=106005010bab1006ce8869b182f9944a\r\nsec-ch-ua-mobile: ?0\r\nX-FourJs-Environment-Variable-REMOTE_ADDR: 127.0.0.1\r\nX-FourJs-Environment-Variable-SERVER_NAME: localhost\r\n\r\nevent _om 0{}{{ConfigureEvent 0{{idRef "86"}{pageSize "21"}{bufferSize "22"}}}}\n
14:33:38.913645 0.425989 [gasrequest.c:1144] 22424 0 REQID=20;HTTP=2;VM=0 "Sending VM" event _om 0{}{{ConfigureEvent 0{{idRef "86"}{pageSize "21"}{bufferSize "22"}}}}\n
14:33:38.914200 0.426546 [gasrequest.c:966] 22424 0 REQID=20;HTTP=2;VM=0 "Receiving VM" om 1 {{an 124 TreeItem 248 {{row "2"} {hasChildren "1"}} {}} {an 124 TreeItem 249 {{row "3"} {hasChildren "1"}} {}} {an 124 TreeItem 250 {{row "4"} {hasChildren "1"}} {}} {an 124 TreeItem 251 {{row "5"} {hasChildren "1"}} {}} {an 124 TreeItem 252 {{row "6"} {hasChildren "1"}} {}} {an 124 TreeItem 253 {{row "7"} {hasChildren "1"}} {}} {an 125 Value 185 {{value "New in 3.20"}} {}} {an 125 Value 186 {{value "New in 3.10"}} {}} {an 125 Value 187 {{value "Language Features"}} {}} {an 125 Value 188 {{value "User Interface"}} {}} {an 125 Value 189 {{value "Compatibility"}} {}} {an 125 Value 190 {{value "WebServices"}} {}} {an 125 Value 191 {{value "WebComponents"}} {}} {an 125 Value 192 {{value ""}} {}} {an 125 Value 193 {{value ""}} {}} {an 125 Value 194 {{value ""}} {}} {an 125 Value 195 {{value ""}} {}} {an 125 Value 196 {{value ""}} {}} {an 125 Value 197 {{value ""}} {}} {an 125 Value 198 {{value ""}} {}} {an 125 Value 199 {{value ""}} {}} {an 125 Value 200 {{value ""}} {}} {an 125 Value 201 {{value ""}} {}} {an 125 Value 202 {{value ""}} {}} {an 125 Value 203 {{value ""}} {}} {an 125 Value 204 {{value ""}} {}} {an 125 Value 205 {{value ""}} {}} {un 86 {{pageSize "21"} {bufferSize "22"}}} {un 182 {{row "1"}}}}\n
14:33:38.914393 0.426738 [gasrequest.c:1533] 22424 0 REQID=20;HTTP=2;VM=0 "Sending UA" HTTP/1.1 200 OK\r\nContent-Type: text/plain\r\nCache-Control: no-cache, no-store\r\nExpires: -1\r\nContent-Encoding: gzip\r\nVary: Content-Encoding\r\nPragma: no-cache\r\n\r\n
14:33:38.914448 0.426792 [gasrequest.c:1534] 22424 0 REQID=20;HTTP=2;VM=0 "Sending UA" om 1 {{an 124 TreeItem 248 {{row "2"} {hasChildren "1"}} {}} {an 124 TreeItem 249 {{row "3"} {hasChildren "1"}} {}} {an 124 TreeItem 250 {{row "4"} {hasChildren "1"}} {}} {an 124 TreeItem 251 {{row "5"} {hasChildren "1"}} {}} {an 124 TreeItem 252 {{row "6"} {hasChildren "1"}} {}} {an 124 TreeItem 253 {{row "7"} {hasChildren "1"}} {}} {an 125 Value 185 {{value "New in 3.20"}} {}} {an 125 Value 186 {{value "New in 3.10"}} {}} {an 125 Value 187 {{value "Language Features"}} {}} {an 125 Value 188 {{value "User Interface"}} {}} {an 125 Value 189 {{value "Compatibility"}} {}} {an 125 Value 190 {{value "WebServices"}} {}} {an 125 Value 191 {{value "WebComponents"}} {}} {an 125 Value 192 {{value ""}} {}} {an 125 Value 193 {{value ""}} {}} {an 125 Value 194 {{value ""}} {}} {an 125 Value 195 {{value ""}} {}} {an 125 Value 196 {{value ""}} {}} {an 125 Value 197 {{value ""}} {}} {an 125 Value 198 {{value ""}} {}} {an 125 Value 199 {{value ""}} {}} {an 125 Value 200 {{value ""}} {}} {an 125 Value 201 {{value ""}} {}} {an 125 Value 202 {{value ""}} {}} {an 125 Value 203 {{value ""}} {}} {an 125 Value 204 {{value ""}} {}} {an 125 Value 205 {{value ""}} {}} {un 86 {{pageSize "21"} {bufferSize "22"}}} {un 182 {{row "1"}}}}\n

Tips for reading VM log files

The VM logs are the output of stdout and stderr and as such do not include a timestamp except when an exception occurs, or when you explicitly include it in the stdout or stderr. For the output you have control over e.g. DISPLAY or writing to stderr via base.Channel.openFile, you may find it helpful to format your information with a timestamp.

The file modification time of the vm log file will tell you when the last line was written to the log file.

No file is produced if nothing is written to stdout or stderr.

When looking at VM log files for a web service, when processes are shutdown they can be in any order so it maybe that the process that is outputting to the *0.log fil has shut down and the *1.log or *2.log etc file is in use.

Tips in General

You can read the log files from the monitor page if you have access.
There is no built-in cleaning mechanism for the log files, it is upto you to implement. The fact each day is written to its own directory should form the basis of your strategy.
There are a number of troubleshooting pages in the GAS documentation, just search on troubleshoot.
Don’t set ALL in categories filter value until you need to, as it makes the log files bigger. If you can reproduce the error at will, set categories filter to ALL, and reproduce.
When reproducing, try and reproduce in a quiet system ie at end of day when all users have logged off so the dispatch log only contains your reproduction.
Send dispatcher and relevant proxy and VM log files for that session. If in doubt zip the whole directory. The online support portal has a max limit of 10Mb for uploads, so if need be zip or make arrangements to send via Dropbox, WeTransfer or something similar.
If you can, get the web server access and error logs. (be aware of clock differences between two servers if any). Also be aware with Apache, the timing of if a line is written when request is received or response is sent.
Become familiar with log output for a clean system so you can spot abnormalities.
If in doubt search for the word Error or error.
If you know the time the issue occurs, tell us, that can save looking through a days log files !