Share This:

Coming to a GA version near you soon is a very useful new supportability feature called Always On Logging (AOL).

 

This feature allows for in-memory logging, which continually maintains a predefined amount of logging regardless of whether any logging was enabled.

 

The primary problems this feature is intended to address, are the cases where the AR Server crashes or other server related events occur where logging hasn't been enabled prior to the event occurring. This feature provides a snapshot of the most recent activity in the server that can be dumped to file for review and analysis. This occurs automatically if the server crashes and can be triggered manually for non crash events.

 

This should help to identify the root cause of issues faster as it ensures that a minimum set of logs is always available.

 

The logging captured consists of the following logs:

  • API
  • SQL
  • Escalation
  • Filter
  • Thread

 

Nothing different is captured other than what you'd normally see in these logs if they were enabled.

 

By default this feature is enabled and AR Server stores a maximum 5 MB of logging in memory.  This has been determined to be an adequate amount of logs to retain in many cases.

 

You can adjust this up or down with the 'In-Memory Log Size (byte):' field on the Server Information form -> Log Files tab (which maps to the 'Memlog-Max:' parameter in the ar.conf/ar.cfg). A value of 0 is supported; and this will disable this feature.

 

 

NOTE: Configuring less than 5 MB will result in less logging being retained and the system will remove older items from the log faster as it is circular in nature. Configuring larger sizes will consume more arserver memory.  Keep this in mind if you decide not to use the default setting.

 

 

The files created will have the following naming convention and are located in the <ARS_HOME>\arserver\db directory along with the other log files:

 

 

                                        UNIX               arserverd.mem.<PID>.<Counter>.log

                                        Windows         arserver.mem.<PID>.<Counter>.log

 

 

If there are multiple logs with the same PID, then the counter will increment by 1.

 

Since the files created are stored in the db directory, these files will be gathered if you run the AR System Maintenance Utility along with all others in this directory. The AR System Maintenance Utility was covered in an earlier Pulse article.

 

AOL is independent of any existing logging that is auto-run by the server (arerror.log or armonitor.log) or that is manually enabled/disabled (API, SQL, Filter logs etc).

 

AOL logs exactly what is going on at that time. For example if there happens to be a surge of Escalation activity that takes up the entire 5 MB log at that point in time, then that is what it would reflect.

 

This file will not be written for an ordinary shutdown (arsystem stop or stop the Service on Windows) unless a crash occurs during the shutdown itself. The same applies if you killed the arserverd/arserver.exe process; a dump file will not be created.

 

This feature will prove invaluable in the case of an unexpected AR Server crash, as it would dump a minimum set of logs without the need to apply logging and wait for the next occurrence.

 

Here's an example of what you'd see in the arerror.log upon a server crash with this new feature:

 

Fri Jan 23 03:28:14 2015: AR System server terminated when a signal/exception was received by the server (ARNOTE  20)

   Thread Id: 7264
   Version: 8.1.00 Build 00 Dec 29 2014 13:17:03
   ServerName: xxx-xxx-xxxx
   Database: SQL -- SQL Server
   Hardware: x86_64
   OS: Windows Server 2008
   RPC Id: 55062
   RPC Call: 35 (IMP)
   RPC Queue: 390600
   Client: User Action Request Installer Account from Remedy Install Kit (RIK) (protocol 20) at IP address 10.173.76.27
   Form:
   Logging On: API SQL
   Code: c0000005
   Operation: read
   Access Addr: 0000000000000008
   Stack Begin:
      Addr: 000000006F926733
      Addr: 0000000000000043
   Stack End
Memlog dump in D:\Program Files\BMC Software\ARSystem\ARServer\Db\arserver.mem.11968.01.log

   Open API Call Table:
      Fri Jan 23 2015 03:25:02: 0.000000 seconds - ArImport (35) by ARSYSTEM (Remedy Install Kit (RIK)), Thread Id = 7264, RPC Id = 55062, Queue Delay = 0 mSec, Result = 0

      Fri Jan 23 2015 00:16:57: 0.000000 seconds - ArMergeEntry (37) by ARSYSTEM (Unidentified Client), Thread Id = 3928, RPC Id = 51433, Queue Delay = 0 mSec, Result = 0
      =====

   Open SQL Call Table:
      Fri Jan 23 2015 00:17:21: 0.000000 seconds - ArMergeEntry (37) by Action Request Installer Account (Unidentified Client), Thread Id = 3928, RPC Id = 51433, Data Time = 0 mSec, Result = 0
    SELECT COUNT(*) FROM T523 WHERE ((T523.C400129200 = 'OI-0007009D60FE40529F0B3FD63D1C09B8') AND (T523.C301016200 IS NOT NULL))

      Fri Jan 23 2015 03:28:13: 0.000000 seconds - ArMergeEntry (37) by Action Request Installer Account (Unidentified Client), Thread Id = 3928, RPC Id = 51433, Data Time = 0 mSec, Result = 0
    SELECT COUNT(*) FROM T523 WHERE ((T523.C400129200 = 'OI-19CE6C3E5D5C4CF0B7E8F8452D5A8740') AND (T523.C301016200 IS NOT NULL))

      Fri Jan 23 2015 00:16:42: 0.000000 seconds - ArBulkEntry (134) by Action Request Installer Account (Unidentified Client), Thread Id = 12540, RPC Id = 35842, Data Time = 0 mSec, Result = 0
    SELECT C301016200 FROM T523 WHERE C1 = '000000000138330'

      Fri Jan 23 2015 00:16:42: 0.000000 seconds - ArMergeEntry (37) by Action Request Installer Account (Unidentified Client), Thread Id = 12644, RPC Id = 33328, Data Time = 0 mSec, Result = 0
    SELECT C301016200 FROM T523 WHERE C1 = '000000000153761'

      Thu Jan 22 2015 21:45:47: 0.000000 seconds - ArMergeEntry (37) by Action Request Installer Account (Unidentified Client), Thread Id = 12644, RPC Id = 33328, Data Time = 0 mSec, Result = 0
    INSERT INTO T873 (C2,C3,C4,C5,C6,C7,C8,C179,C300204600,C300664200,C300679800,C300762700,C300928500,C300967500,C300967600,C300967700,C300967800,C301403100,C301600300,C301629900,C302890700,C302998800,C303453900,C303454000,C303454100,C303454200,C303459100,C303998000,C304003400,C304249200,C304249720,C304351141,C304351251,C304351271,C304352331,C304352341,C304352351,C304352361,C304352371,C304352561,C304352571,C304352931,C304352941,C304352951,C304352961,C304353081,C304353091,C304353101,C304353111,C304353501,C304353961,C304354981,C304354991,C304355001,C304355011,C304355021,C304355031,C304355041,C304355051,C304355061,C304355071,C1000000077,C1000000564,C1000001136,C1000001176,C1000001447,C1000001802,C304357881,C1) VALUES ('dev_awon',1385686225,NULL,'dev_kishah',1385686356,0,'NOT USED','AGGAA5V0HII0BAMXAC2BBAMAKH43QX',NULL,NULL,0,'Remedy Asset Inventory','ASI_UPDATE_REQUEST_TYPE','ASI','AST:AssetPeople',NULL,6,NULL,'config-asi-post',NULL,NULL,'ITSM',NULL,NULL,'Update existing records where REquest_Type is NULL',1,'-','+','SUBSTRING',NULL,NULL,NULL,NULL,'18000',NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,'000000000005962')

      Thu Jan 22 2015 22:34:29: 0.000000 seconds - ArBulkEntry (134) by Action Request Installer Account (Unidentified Client), Thread Id = 2040, RPC Id = 2463Fri Jan 23 03:28:13 2015  390600 : AR System server terminated when a signal/exception was received by the server (ARNOTE 20)
Fri Jan 23 03:28:13 2015     0xc0000005
Fri Jan 23 03:28:13 2015  390600 : AR System server terminated - fatal error occurred in ARSERVER (ARNOTE 21)
             

arerror.log snippet

 

 

Notice that a line is written just after the stack trace informing you of the Memlog dump file that corresponds to this server crash.

Also notice the Open API Call Table and Open SQL Call Table sections, this is part of the Server Statistics feature and was introduced in 7.6.04 SP5 & 8.1.01.

 

Here is a snippet of the corresponding AOL memlog file:

 

; Server-Name: xxx-xxx-xxxx
; at 1422001693 Fri Jan 23 2015 03:28:13


<SQL > <TID: 0000007264> <RPC ID: 0000055062> <Queue: Admin     > <Client-RPC: 390620   > <USER: Action Request Installer Accou               > <Overlay-Group: -2        > /* Fri Jan 23 2015 03:27:09.2950 */OK
<SQL > <TID: 0000007264> <RPC ID: 0000055062> <Queue: Admin     > <Client-RPC: 390620   > <USER: Action Request Installer Accou               > <Overlay-Group: -2        > /* Fri Jan 23 2015 03:27:09.3110 */DELETE FROM field_enum_values WHERE schemaId = 2057 AND fieldId = 1000000181
<SQL > <TID: 0000007264> <RPC ID: 0000055062> <Queue: Admin     > <Client-RPC: 390620   > <USER: Action Request Installer Accou               > <Overlay-Group: -2        > /* Fri Jan 23 2015 03:27:09.3110 */OK
<SQL > <TID: 0000007264> <RPC ID: 0000055062> <Queue: Admin     > <Client-RPC: 390620   > <USER: Action Request Installer Accou               > <Overlay-Group: -2        > /* Fri Jan 23 2015 03:27:09.3110 */INSERT INTO field_enum_values (recordId,schemaId,fieldId,enumId,value) VALUES (222921,2057,1000000181,1000,'Project')
<SQL > <TID: 0000007264> <RPC ID: 0000055062> <Queue: Admin     > <Client-RPC: 390620   > <USER: Action Request Installer Accou               > <Overlay-Group: -2        > /* Fri Jan 23 2015 03:27:09.3110 */OK
<SQL > <TID: 0000007264> <RPC ID: 0000055062> <Queue: Admin     > <Client-RPC: 390620   > <USER: Action Request Installer Accou               > <Overlay-Group: -2        > /* Fri Jan 23 2015 03:27:09.3110 */INSERT INTO field_enum_values (recordId,schemaId,fieldId,enumId,value) VALUES (222922,2057,1000000181,2000,'Change')
<SQL > <TID: 0000007264> <RPC ID: 0000055062> <Queue: Admin     > <Client-RPC: 390620   > <USER: Action Request Installer Accou               > <Overlay-Group: -2        > /* Fri Jan 23 2015 03:27:09.3110 */OK
.
..
...
<FLTR> <TID: 0000003928> <RPC ID: 0000051433> <Queue: Fast      > <Client-RPC: 390620   > <USER: Action Request Installer Accou               > <Overlay-Group: -1        >    --> Failed qualification
<FLTR> <TID: 0000003928> <RPC ID: 0000051433> <Queue: Fast      > <Client-RPC: 390620   > <USER: Action Request Installer Accou               > <Overlay-Group: -1        > /* Fri Jan 23 2015 03:28:13.4920 */     <Filter Level:1 Number Of Filters:49734> Checking "ASI:AEO:ResetPrimaryContact_100" (100)
<SQL > <TID: 0000003928> <RPC ID: 0000051433> <Queue: Fast      > <Client-RPC: 390620   > <USER: Action Request Installer Accou               > <Overlay-Group: -1        > /* Fri Jan 23 2015 03:28:13.4920 */SELECT C1,C2,C3,C4,C5,C6,C7,C8,C112,C179,C200000006,C260000001,C260100002,C260100003,C260100005,C260100006,C260100008,C260100009,C260100010,C260100011,C260100012,C260100013,C260100014,C260100021,C300839200,C301104100,C301104200,C301497700,C301501300,C301501400,C301600300,C301763400,C304040600,C400079600,C1000000010,C1000000082,C1000002883,C1000002884,C301016200,C304327610,C530009700,C530010600,C530048500,C530054200 FROM T1496 WHERE C1 = '000000000008312'
<SQL > <TID: 0000003928> <RPC ID: 0000051433> <Queue: Fast      > <Client-RPC: 390620   > <USER: Action Request Installer Accou               > <Overlay-Group: -1        > /* Fri Jan 23 2015 03:28:13.4920 */OK
<FLTR> <TID: 0000003928> <RPC ID: 0000051433> <Queue: Fast      > <Client-RPC: 390620   > <USER: Action Request Installer Accou               > <Overlay-Group: -1        >    --> Failed qualification
<FLTR> <TID: 0000003928> <RPC ID: 0000051433> <Queue: Fast      > <Client-RPC: 390620   > <USER: Action Request Installer Accou               > <Overlay-Group: -1        > /* Fri Jan 23 2015 03:28:13.4920 */     <Filter Level:1 Number Of Filters:49735> Checking "ASI:AEO:SetPrimaryCapability_110" (100)
<FLTR> <TID: 0000003928> <RPC ID: 0000051433> <Queue: Fast      > <Client-RPC: 390620   > <USER: Action Request Installer Accou               > <Overlay-Group: -1        >    --> Passed -- perform actions
<FLTR> <TID: 0000003928> <RPC ID: 0000051433> <Queue: Fast      > <Client-RPC: 390620   > <USER: Action Request Installer Accou               > <Overlay-Group: -1        >         0: Set Fields
<SQL > <TID: 0000003928> <RPC ID: 0000051433> <Queue: Fast      > <Client-RPC: 390620   > <USER: Action Request Installer Accou               > <Overlay-Group: -1        > /* Fri Jan 23 2015 03:28:13.4920 */SELECT TOP 2  T523.C1 FROM T523 WHERE ((T523.C400129200 = 'OI-19CE6C3E5D5C4CF0B7E8F8452D5A8740') AND (T523.C301016200 IS NOT NULL)) ORDER BY 1 ASC
             

AOL memlog snippet

 

For the most part, upon a server crash is when this feature would be used. An example of when you would use the 'Dump to File' option would be if you are experiencing abnormal behaviour and then you can manually intervene in order to generate the physical file so that it can be analysed.

 

Server Info Log Files.png

In-Memory Log Size field and Dump to File button

 

To generate the file on-demand, navigate to the Server Information form -> Log Files tab and click the 'Dump to File' button. This will dump the current contents of the logs stored in memory to a file, and once complete a pop-up will appear displaying the filename.

 

In-memory log dumped to.png

 

Using the 'Dump to File' button flushes the current contents of the In-Memory logging, so once dumped any logging stored in-memory will be new.

 

You'll have to go to the machine hosting AR Server to retrieve the file contents, as there is no way to view it via the application (as is with API, SQL etc logs).

 

 

You can use the driver program (introduced here) with this new feature to:

  • find out the last dump file name (420) and in-memory log size (421), using the GSI command
  • set the in-memory log size, using the SSI command
  • generate a dump file, using the PROC command

 

driver gsi.png

driver Get Server Information (gsi) call

 

driver proc.png

driver Execute Process (proc) call

 

Always On Logging comes preconfigured upon install and it is enabled by default. It is initiated when the server starts up and will begin to capture logs.