Tag: Logging

Suppressing SAS Workspace Server MVA_DSIO.OPEN_CLOSE and _DISARM Messages

This is just a very quick post to jot down the location of a SAS reference that I keep losing! I have the SAS Audit, Performance and Measurement (APM) package installed in my older SAS 9.4 M0 dev/test environment. The APM package is now deprecated as the functionality has moved into SAS Environment Manager (from 2.4). One of the effects of having APM installed is that my SAS Workspace Server logs have a huge number of lines that look like this: 

NOTE: MVA_DSIO.OPEN_CLOSE| _DISARM|         STOP| _DISARM| 2016-07-31T15:44:27,279+10:00| _DISARM| WorkspaceServer| _DISARM| | 
      _DISARM| | _DISARM| | _DISARM| 9854976| _DISARM| 12| _DISARM| 12| _DISARM| 320| _DISARM| 1840| _DISARM| | _DISARM| | _DISARM| 
      | _DISARM| | _DISARM| | _DISARM| | _ENDDISARM 
NOTE: PROCEDURE| _DISARM|         STOP| _DISARM| 2016-07-31T15:44:27,279+10:00| _DISARM| WorkspaceServer| _DISARM| | _DISARM| | 
      _DISARM| | _DISARM| 9854976| _DISARM| 12| _DISARM| 12| _DISARM| 728| _DISARM| 1840| _DISARM| | _DISARM| | _DISARM| | _DISARM| 
      | _DISARM| | _DISARM| | _ENDDISARM

Sometime I want to suppress those lines (without uninstalling SAS APM). I then remember there’s a SAS page that contains instructions on how to do it, and spend several minutes trying to find it. I keep looking for a SAS Usage Note, but instead it’s a gem at the end of the SAS APM FAQ page: “Why do the Enterprise Guide SAS logs contain messages related to MVA_DSIO.OPEN_CLOSE and _DISARM? How can these messages be eliminated from the SAS log for EG users?”.

Essentially you edit the workspace server’s logconfig.apm.xml and change the Threshold of the WSLogAppender to Error.

You’ll want to pay attention to the note in the FAQ that says it will disable the SAS DI Studio Job Statistics features. I don’t use that feature in this environment, but you might!

SAS & IWA: Check the Logs

When testing Integrated Windows Authentication (IWA) based client connections to SAS® platform servers, it is well worth checking the SAS logs to verify the connections are being made the way you expect. SAS has a variety of methods up it’s sleeve to get you authenticated, including cached credentials, retrieving stored credentials from metadata, SAS token authentication etc. Looking in the SAS server logs will help you identify the connection/authentication events and methods used. In the past I’ve thought I was using IWA+Kerberos but when I looked in the log it was obvious I wasn’t! I think it’s essential when testing/troubleshooting a new IWA configuration to review the SAS server logs for both failed and successful connections.

In a previous post “SAS and IWA: Two Hops” I mentioned how sometimes it’s necessary to force the use of Kerberos with IWA to be able to make IWA delegated connections to secondary servers. So here’s some examples of what we might see in SAS server logs Continue reading “SAS & IWA: Check the Logs”

Dynamic Logging Reconfiguration in SAS® 9.3

One of the exciting new features in SAS 9.3 (well for me anyway) is the ability to replace or modify the logging configuration on-the-fly for a running server without needing to restart it. Previously in SAS 9.2 you could dynamically change the levels for loggers on servers (via SAS Management Console Server Manager Loggers tabs) but not modify the appender configuration. Now in SAS 9.3 you can completely change the logging configuration file and apply it without restarting the server. This is exciting because it means you can do something like add a new appender for a new custom log file for the metadata server in the middle of the day with out having to restart the entire platform of dependant services. That’s really neat!

I tried it out. I made a small change to the metadata server logconfig.xml, saved it, and then waited … watching the log file. I’d thought that maybe the servers had a watchdog thread to monitor changes to the log config file (a bit like the log4j’s configureAndWatch) but after watching and waiting for a little while nothing happened. I then checked the documentation (always a good idea) and found that you actually need to prod the server to tell it to change its logging config via proc iomoperate (also new in SAS 9.3).

This is the code I used to tell the SAS Metadata Server to reload its logging configuration file (logconfig.xml) – the one I had changed.

proc iomoperate;
connect host='sas93lnx01' port=8561 user='sasadm@saspw' password='thesecretpassword';
set log cfg="/opt/ebiedieg/Lev1/SASMeta/MetadataServer/logconfig.xml";
quit;

It worked. The metadata server immediately closed it’s current log file (SASMeta_MetadataServer_2012-01-10_sas93lnx01_1266.log) and opened a new one with a _0 suffix (SASMeta_MetadataServer_2012-01-10_sas93lnx01_1266.log_0) using the modified config. I wondered why it had added the _0 suffix? Subsequent executions increase the log file suffix (_1, _2, etc.). Perhaps it was done to delineate the old and new logging config in case someone wanted to parse the logs? If anyone knows how to make it continue to log to the same log file I’d love to know.

Of course this dynamic logging reconfiguration also means you can readily switch between normal and trace level logging config files to troubleshoot a problem and then switch back again quickly – all without a restart. Something like this:

* switch to trace log configuration;
proc iomoperate;
connect host='sas93lnx01' port=8561 user='sasadm@saspw' password='thesecretpassword';
set log cfg="/opt/ebiedieg/Lev1/SASMeta/MetadataServer/logconfig.trace.xml";
quit;

* >>> REPLICATE THE PROBLEM;
* switch back to normal log configuration;
proc iomoperate;
connect host='sas93lnx01' port=8561 user='sasadm@saspw' password='thesecretpassword';
set log cfg="/opt/ebiedieg/Lev1/SASMeta/MetadataServer/logconfig.xml";
quit;

For more info check out the following SAS documentation references:

Troubleshooting: sas.servers & hostname aliases

SAS® Service Management Script for Linux and UNIX: sas.servers I ran into an interesting problem over the last few days with my SAS® 9.3 deployments on Linux. I had noticed that the sas.servers scripts for my Lev2 and Lev3 deployments were taking several minutes to start the SAS services. I know JBoss takes ages to start but usually the SAS services start really quickly. I had assumed Remote Services was the culprit, but surprisingly it turned out to be starting the SAS/CONNECT Job Spawner service that was the problem. Even more surprisingly the underlying cause turned out to be the use of the hostname in the log filename where the deployment logical hostname alias used during deployment was different to the physical hostname of the machine it was deployed on.

To start the troubleshooting process I modified the sas.servers script to add some timing information to the console log messages it generated. Editing the sas.servers script is not necessarily the best option but more on that later. The sas.servers script has a function called logmsg which seems to have been very nicely provided in order to customize its logging. I wanted to make a simple change to add a time stamp so I could see where all the time was being spent. I changed the function from this (reformatted and comments omitted for brevity):

logmsg() {
    echo "$*"
}

… to this:

logmsg() {
    DT=`date +%Y-%m-%d:%H:%M:%S`
    echo "$DT: $*"
}

I stopped the services since they were already running:

root@sas93lnx01:~# cd /opt/ebiedieg/Lev3
root@sas93lnx01:/opt/ebiedieg/Lev3# ./sas.servers stop
2011-10-30:21:51:31: Stopping SAS servers

Then checked they were all stopped:

root@sas93lnx01:/opt/ebiedieg/Lev3# ./sas.servers status
2011-10-30:21:51:59: SAS servers status:
2011-10-30:21:51:59: SAS Metadata Server 1 is NOT up
2011-10-30:21:51:59: SAS OLAP Server 1 is NOT up
2011-10-30:21:51:59: SAS Object Spawner 1 is NOT up
2011-10-30:21:51:59: SAS Share Server 1 is NOT up
2011-10-30:21:51:59: SAS CONNECT Spawner 1 is NOT up
2011-10-30:21:51:59: SAS Remote Services 1 is NOT up
2011-10-30:21:51:59: SAS Framework Data Server 1 is NOT up

Once stopped, I started them again so I could see where all the time was spent:

root@sas93lnx01:/opt/ebiedieg/Lev3# ./sas.servers start
2011-10-30:21:54:54: Starting SAS servers
2011-10-30:21:55:03: SAS Metadata Server 1 is UP
2011-10-30:21:55:07: SAS OLAP Server 1 is UP
2011-10-30:21:55:11: SAS Object Spawner 1 is UP
2011-10-30:21:55:11: SAS Share Server 1 is UP
2011-10-30:21:56:12: SAS CONNECT Spawner 1 is NOT up
2011-10-30:21:56:28: SAS Remote Services 1 is UP
2011-10-30:21:56:32: SAS Framework Data Server 1 is UP

Total time to start was 98 seconds. Not too bad really but it should be quicker than that. Everything seemed to start within a few seconds of each other except for the the SAS/CONNECT Job Spawner! It looked like I was wrong to assume it was Remote Services. The SAS/CONNECT Job Spawner appeared to be taking 60 seconds to apparently not start. It had started though. This was confirmed by looking in the process list and the job spawner log file. It all seemed very odd and for 2 reasons: firstly the job spawner is usually very fast to start and secondly 60 seconds is a bit of a convenient number; it sounded like a timeout.

The sas.servers script starts each SAS service in turn waiting for the service to become available before starting the next one. It sounded like sas.servers was waiting for some event from the job spawner and gave up after 60 seconds assuming it had not started. Time to dig into the sas.servers script a bit more.

The SAS/CONNECT job spawner is started by the sas.servers script in the start_connect_spawner function. It spawns the spawner (ConnectSpawner.sh start) in the background and then calls the is_atypical_server_up function to wait for it to finish starting. Looking into the is_atypical_server_up function it seems to repeatedly sleep and grep the job spawner log for some trigger text. Effectively:

grep "SAS Job Spawner for Open Systems" /opt/ebiedieg/Lev3/ConnectSpawner/Logs/ConnectSpawner_sas93lnx01.log

Now I could see the problem. It was scanning a non-existant log file ConnectSpawner_sas93lnx01.log when it should be scanning the ConnectSpawner_sas93lnx03.log file which was actually being written to by the job spawner. The log file name contained the wrong hostname. The name sas93lnx01 was the physical name of the machine, but sas93lnx03 was the host name alias I used when deploying the Lev3 environment. I prefer to use host name aliases in deployments for the benefits they provide in being able to easily move deployments between physical machines and provide disaster recovery options. In this case the Lev3 environment was currently on the same machine as the Lev1 environment, but I knew one day I would move it onto another machine so had used a host name alias sas93lnx03 (a DNS CNAME record) which I could easily redirect later to the appropriate physical machine name (DNS A record).

There was the problem. The SAS/CONNECT job spawner was using the deployment/logical hostname alias whereas the sas.servers script was using the physical hostname (which it got from `uname -n`). With the wrong log file name it could never find the log file and therefore never see the trigger text and would always time out after 60 seconds.

There were at least two ways I could fix this problem. The first was to modify the ConnectSpawner.sh script to use the physical host name, rather than deployment host name alias, in the log file name. The second was to modify the sas.servers script to use the deployment hostname alias instead of the physical host name. That was the option I chose. It was the slightly more difficult of the two but I didn’t feel right telling the job spawner to log to a file with the wrong name :)

These were the changes I made to sas.servers to get it to work. Firstly I added an extra line where the SHOSTNAME environment variable is derived, changing this:

SHOSTNAME=`uname -n`

… to this:

SHOSTNAME=`uname -n`
SHOSTNAME_ALIAS="sas93lnx03"

Secondly I modified the start_connect_spawner function to change the name of the log file (as checked by the is_atypical_server_up function) from this:

SLOGNAME="ConnectSpawner_${SHOSTNAME}"

… to this:

SLOGNAME="ConnectSpawner_${SHOSTNAME_ALIAS}"

As it happens, the same problem occurs with the deployment tester server component too so I also edited the start_deployment_testsrv function changing this:

SLOGNAME="DeploymentTesterServer_${SHOSTNAME}"

… to this:

SLOGNAME="DeploymentTesterServer_${SHOSTNAME_ALIAS}"

However, there is a potential problem with this method of editing sas.servers directly; I alluded to it earlier in the post. The sas.servers script is a generated script and any edits made to it will get wiped out if/when it is regenerated at a later date. The SAS documentation for the sas.servers script cautions against editing the script. The sas.servers script is created by the generate_boot_scripts.sh script. Next time someone or something runs generate_boot_scripts.sh the changes to sas.servers will be lost.

To protect against this you could modify the templates that are used by generate_boot_scripts.sh. This is what I did. I made all the same changes described above in the single template /opt/ebiedieg/Lev3/Utilities/script_templates/sas.servers.mainlog so they would survive a regeneration. I wouldn’t necessarily recommend this though. It’s not a method documented by SAS Institute and I suspect these templates will most likely get changed at some point during a SAS software upgrade or hotfix. However, it works for me for the time being. Looking back it probably would have been better to just changed the ConnectSpawner.sh script to use the wrong hostname ;)

With those changes done it was time to stop and start the servers to see any improvements:

root@sas93lnx01:/opt/ebiedieg/Lev3# ./sas.servers start
2011-10-30:23:54:30: Starting SAS servers
2011-10-30:23:54:39: SAS Metadata Server 1 is UP
2011-10-30:23:54:43: SAS OLAP Server 1 is UP
2011-10-30:23:54:47: SAS Object Spawner 1 is UP
2011-10-30:23:54:47: SAS Share Server 1 is UP
2011-10-30:23:54:49: SAS CONNECT Spawner 1 is UP
2011-10-30:23:55:06: SAS Remote Services 1 is UP
2011-10-30:23:55:10: SAS Framework Data Server 1 is UP

This time only 40 seconds (less than half the original time) and the SAS CONNECT Job Spawner is now reported as being up.

As it turns out, I noticed that several of the other SAS services (like the metadata server) use the physical host name in their log filenames. It all works fine but I would have preferred they used the deployment hostname if it were possible. I briefly looked into ways of telling those servers to use the logical hostname alias instead but, since they use the SAS logging framework and the %S{hostname} conversion pattern, I couldn’t see any obvious way other than editing all of the config files and scripts post deployment. If someone knows a good way of consistently and automatically using the deployment hostname (the one providing during deployment and potentially different from the physical hostname) during installation then I’m all ears :)

Which logger did that SAS log message come from?

Occasionally you might want to generate a custom SAS log file, perhaps to be parsed and analysed to generate a custom report. You want to focus on a specific subset of messages and already know that you can modify the logging configuration file and attach the logger that generates the message to an appender to write the messages to your custom log file. The only thing you don’t know is which logger in particular is generating the messages you want to capture. You can see the messages you want already in the main log file but don’t know which logger is generating them. Is it App.Meta, Audit.Meta.Security, Audit.Authentication or something else? How do you find out which logger you need?

In situations like this I temporarily modify the logging configuration file (usually logconfig.xml) to add the conversion character %c to the ConversionPattern setting. This adds the logger name into the message. Restart the server in question and then look for the source of the interesting messages. Normally I only do this on a development server so I might leave the change in place so I can easily find the right logger next time.

Here’s an example of the ConversionPattern param in the SAS metadata server logging configuration file before the change:

<param name="ConversionPattern" value="%d %-5p [%t] %X{Client.ID}:%u - %m"/>

… and here’s the same param after adding in a “(%c)”:

<param name="ConversionPattern" value="%d %-5p [%t] (%c) %X{Client.ID}:%u - %m"/>

… and finally here’s a SAS metadata server log file fragment showing the result of the change:

2011-05-19T16:34:31,524 INFO  [00000004] (Admin.Operations) :sas - SAH011001I SAS (9.2) Metadata Server (8562), State, starting
2011-05-19T16:34:31,754 INFO  [00000008] (App.Meta) :sas - OMACONFIG option OMA.SASSEC_LOCAL_PW_SAVE found with value 1 and processed.
2011-05-19T16:34:31,755 INFO  [00000008] (App.Meta) :sas - Unable to load AES encryption algorithm. Using SASPROPRIETARY for password storage.
2011-05-19T16:34:31,755 INFO  [00000008] (App.Meta) :sas - Using SASPROPRIETARY for password fetch.
2011-05-19T16:34:31,760 INFO  [00000008] (Audit.Meta.Security) :sas - SAS Metadata Authorization Facility Initialization.
2011-05-19T16:34:31,761 INFO  [00000008] (Audit.Meta.Security) :sas - SAS is an adminUser.
2011-05-19T16:34:31,769 INFO  [00000008] (Audit.Meta.Security) :sas - SASTRUST@SASPW is a trustedUser.
2011-05-19T16:34:31,771 INFO  [00000008] (Audit.Meta.Security) :sas - SASADM@SASPW is an unrestricted adminUser.
...
2011-05-19T16:35:42,227 INFO  [00000164] (Audit.Authentication) :sasadm@saspw - New client connection (8) accepted from server port 8562 for user sasadm@saspw.  Encryption level is Credentials using encryption algorithm SASPROPRIETARY.  Peer IP address and port are [127.0.0.1]:52947.

Now I can see where the messages are coming from. Perhaps the Audit.Authentication message is the one I want.

You can find out more about conversion characters and configuring custom logging by reading the document SAS® 9.2 Logging Configuration and Programming Reference available from support.sas.com (PDF, HTML).

Update 20May2011: I forgot to mention that if you are generating a custom log file for the purposes of audit or performance logging, you might want to look first at the SAS 9.2 Enterprise Business Intelligence Audit and Performance Measurement instrumentation package. It might already provide what you need and if not then you might be able to make some small customisations rather than start from scratch.