Processes Mysteriously Being Deleted

[Robert Atkinson]

We have a problem that's now happened for a 3rd year in a row. Over the Christmas period a couple of our batch jobs have terminated, like this :-

Entry  Jobname         Username     Blocks  Status
  -----  -------         --------     ------  ------
    324  GBSINVRUN       BATCHUSER             Retained on error
       %SYSTEM-F-EXITFORCED, forced exit of image or process by SYS$DELPRC
         On available batch queue BETA$OPERATIONS
         Completed 31-DEC-2007 07:45:52.97 on queue BETA$OPERATIONS

We cannot find a reason for this. Is only effects a couple of processes each year, and only happens at Christmas.

We Autogen/reboot every month, so it's not a 'build-up' type issue.

What I'd like to know is if anyone else has seen anything that matches this profile - could there be a VMS virus that only effects a few systems?

Rob.

[Hein van den Heuvel]

>> Over the Christmas period a couple of our batch jobs have terminated

So this happened over multiple days?
So we can not blame say an idle process killer which got nervous (miscalculated) year-end? Anyway, the example shown is too far away from new-year even fudging in UTC consideration (looks like local time = utc for you).


>> this. Is only effects a couple of processes each year, and only happens at Christmas.

I think someone wants to go home early?!
Sorry, not obvious explanation.


>> We Autogen/reboot every month, so it's not a 'build-up' type issue.

Why would you want to do that? Oh well.
Does that reboot come with process deletes?
Are the processes targetted just (much) longer running than anticapted aroudn Xmass?


>> could there be a VMS virus that only effects a few systems?

Ah, finally a simple, one word, answer: NO.
Two words? NO WAY!

grins,
Hein.

[Hoff]

You'll want to enable auditing of privileges or auditing of process control system services, so that you can capture the $delprc or $forcex call for next year. Or set yourself a calendar event for mid December 2008, and enable the requisite auditing then. (You might want to have at least some of this auditing enabled as a matter of course.)

If the processes are the approximate same set each year (check last year's accounting, if you still have it on-line or in your BACKUP archives), it is easily possible that the code itself is detecting the end of the year as part of its normal processing (as I'm guessing the code is date-related, based on that name), and it's failing and/or forcing an exit.

Look for patterns.

Look for application code messing with scheduling or with system time, or with time-change or TDF-related events, or other such code. (If you don't have application code, check with the vendor or whomever has the code.)

As for malware, an underlying operating system bug, or most any other out-of-band and external trigger for an error such as this, a site-local tool or procedure or a latent application error is a far more likely trigger for this sort of behavior.

The so-called "built-up" issues are generally also signs of application errors, or process errors. OpenVMS is quite capable of running for a decade, barring the standard maintenance and requisite patches. I'd not bother with a monthly reboot and an AUTOGEN pass, save for cases where there are large-scale changes in load.

I would look to cases such as file versions approaching 32K (tools such as DFU, or updates to the DIRECTORY command in recent OpenVMS versions can help here), and toward cruft "building up" in indexed files, and related. There are cases where cruft can build up, but these are generally due to the way the application operates, or operates with OpenVMS. Reboots won't generally cure these cases, either.

Malware is certainly quite possible on OpenVMS, but you do need to ask yourself "am I really a target?" and "am I the first site to see malware in the wild on OpenVMS since, well, CCC and WANK?". And you need to ask yourself "how did I get infested?", as transmission is rather difficult using the typical PC vectors of mail and web. If you're handling boatloads of assets, you might well be a specific malware target. But otherwise, hearing hoof beats usually mean horses, and not zebras. This means application and process bugs, then maybe OpenVMS or LP bugs, and not malware.

[Jon Pinkley]

Is it possible you have some type of process watcher that is looking for "runaway" processes and it is deleting the processes? Perhaps due to seasonality, the processes are taking more resources than they normally do, and thus appear to be in a loop.

Have you looked at accounting records for the resources used by the processes that are being deleted? If you have image accounting turned on, this would also be helpful. Even more helpful would be audit records if

$ set audit/audit/enable=(process=all)

is in effect, or for only monitoring $DELPRC events:

$ set audit/audit/enable=(process=delprc)

Before next year's Christmas period, you may want to turn on process auditing and possibly image accounting.

Is there special year end processing that must complete before 1-jan? (Looking at the 31-DEC-2007 date).

A bit more about image accounting:

Image accounting can consume disk space quickly if you have many image rundowns. But disk space is the primary resource it consumes. We run with image accounting on all the time. A side benefit of having image accounting turned on is that the CTL$xx_I* cells in the process control region are populated when images startup, so for example it is possible to determine when an image started while it is currently running by using something like this:

SDA> set proc/in=20207802
SDA> exam/time ctl$gq_istart
15-JAN-2008 13:12:07.46
SDA>

To enable image accounting:

$ SET ACCOUNTING /ENABLE=IMAGE

See help set accounting for more info.

Image accounting records can be surprisingly useful for troubleshooting. So can audit records.

Jon

[John Gillings]

Rob,

Since you're only getting once a year shots at this, you should turn on more auditing than you think you need to make sure you can follow leads. In addition to PROCESS audits as already suggested, I'd also recommend both LOGIN and LOGOUT audits:

$ SET AUDIT/AUDIT=(LOGIN=ALL,LOGOUT=ALL)

So, when your enable=(process=delprc) audit tells you some random process did it, you can determine when and from where that process was created. Since it's OpenVMS, you should probably enable your audits well in advance (perhaps just BEFORE a reboot prior to the expected event). That way you can be certain you'll have a record of all the processes that might be responsible.

If you have sufficient storage and processing power, you could take the thermonuclear option and enable ALL auditing for the suspect period. (believe it or not, I've seen systems with full auditing enabled, but they were specifically sized with extra CPUs and storage to cope with the auditing load, and if I told you where they were I'd have to shoot you ;-)

[Thomas Ritter]

Robert, was there a log file associated with this batch job ?

[DECxchange]

Did you do a:
$ show que/all/full

on this queue? Or if you leave out the queue name, it will list all of the information for every queue on your system. You can scroll back and see what file was submitted, what time it was submitted, and what qualifiers were used. Then you can work your way backwards and forwards to figure out what the job is doing and why it might be getting stopped. You could add commands to the command file that is being run to identify when and where it is getting stopped.

[Wim Van den Wyngaert]

If you analyze the moment of process deletion with VPA or whatever, you could find which programs were also active around that moment and may be find the guilty one (just hope it's called christmas_process_del.exe).

Also accounting could reveal something.

Bush would say "It's Al-Qaeda. Lets bomb Iran.".

Wim

[Robert Atkinson]

Many thanks for all of the responses. If I can deal with some of the simple answers first.....

We don't use a process monitor/killer anywhere on the system, so I think this can be ruled out.

We used to Autogen every week, but have dropped to monthly - 2nd week in the month. There are pros and cons to this frequency, which I don't want to discuss here and detract from the initial problem.

The application we run does the same thing, day in, day out. The same sets of programs are used, running the same data against the same code.

It's very unlikely that something exists in the application software, especially as some of the DELPRC events have occurred whilst the bagtch job has been running DCL WAIT commands.

Completely agree with enabling auditing towards the end of 2008, and we've switched some extra events on already, however, we only see this problem near the end of the year.

I'm doing some extra checking on exactly when this problem has ocurred, as it may be we're running a program during our yearend that effects VMS in some way, and shows up a day or two later.

Sorry for not including this earlier, but this is what DIAG thinks of it :-

**** V3.4 ********************* ENTRY 533 ********************************





Logging OS 1. OpenVMS

System Architecture 2. Alpha

OS version V7.3-2

Event sequence number 18983.

Timestamp of occurrence 31-DEC-2007 07:45:52

Time since reboot 15 Day(s) 16:50:36

Host name BETA



System Model AlphaServer ES45 Model 2B



Entry Type 40. System Bugcheck



Bugcheck Minor class 2. System Bugcheck



Bugcheck Msg RMSBUG, RMS has detected an invalid

condition

Process ID x007E0097

Process Name GBSINVRUN

KSP x000000007FF88000

ESP x000000007FF8BC74

SSP x000000007FF9CD70

USP x000000007AD51A70

R0 x0000000000000001

R1 x0000000000000001

R2 xFFFFFFFFFFFFFFFA

R3 xFFFFFFFF8A9022A0

R4 xFFFFFFFF8A9025B0

R5 x0000000000000000

R6 x0000000000018001

R7 x0000000000000000

R8 x000000007FFCEE24

R9 x000000007FFD0218

R10 x0000000000000001

R11 x000000007FFD00B8

R12 x000000007FFCDA60

R13 xFFFFFFFF8A90DEA8

R14 xFFFFFFFF819E6080

R15 x000000007AE4DE20

R16 x00000000000003A0

R17 xFFFFFFFFFFFFFFFA

R18 x0000000000000004

R19 x000000007FFD0010

R20 x000000007FFD0010

R21 xFFFFFFFF8A914360

R22 x00000000FFFFFFFF

R23 x0000000000000064

R24 x0000000000000001

R25 x0000000000000001

R26 xFFFFFFFF8049A200

R27 xFFFFFFFF8A90DEA8

R28 xFFFFFFFF8049B354

FP x000000007FF8BC80

SP x0041474D24415445

PC xFFFFFFFF804A3550

PS x0000000000000009


Last year, our support company suggested this may have been caused by PIOPAGES being set too low, so we upped it to 2000. As you can see, it hasn't helped so far.

Rob.

[Hein van den Heuvel]

Ah, but that's an RMS Bugcheck.

Specifically

FFFFFFFA == ASBALLFAIL == couldn't allocate an asb (rm0stall)

RMS ran out of stack more or less.

Are you up to date on OpenVMS and patches?

RMS crashed zap the process.
For full analysis you may have to run with SYSGEN BUGCHECK_FATAL = 1.
This will crash the syste, on an RMS bugcheck.


more later... gotta run

Hein.

[Robert Atkinson]

> Are you up to date on OpenVMS and patches?

Yes, VMS 7.3-2 fully patched - we will probably be on VMS 8.3 when this comes around next year.

BUGCHECKing the system is probably not an option, as it happens at our busiest time of the year - we're a book distributor!

Rob.

[Gregg Parmentier]

Robert,

Do the programs process future data times? Is it possible that at 7:45 AM they are processing data associated with the following year for the first time?
If you're calculating something based upon differences in time (that effects memory allocation or some other resource allocation), and you get a negative number because the program is just using month and day and not paying attention to year, I can see a problem that would occur every late December.

[Robert Atkinson]

The prgramming language takes care of dates/times, so that wouldn't cause a problem, plus it wouldn't explain why the error can occurr in DCL.

[Willem Grooters]

It doen't have to be DCL. SYS$DELPRC - something stopped the process:

Process ID x007E0097

Process Name GBSINVRUN

A few thoughts:

I think accounting won't tell more, just DELPRC. If a RMS bugcheck forces process deletion using SYS$DELPRC, it's nasty if that information is lost....

Out of stack + busiest time of the year: If it is an RMS issue, I think it might be something in the program causing the stack to get exhausted, where 'normal' load willbe within limits. Too many concureent reads/writes, perhaps? Too many channels/files open?

[Robert Atkinson]

Willem, I think you misunderstood my last comment.

What I meant was that the failure can happen inside an application program and whilst the batch job is running DCL commands, so it's probably nothing to do with the application.

Rob.

[Willem Grooters]

Agreed - a batch process runs a DCL procedure - but the procedure can run an image. The problem could happen in the image, causing the process to be deleted (to prevent even more damage). The message is clear enough: "forced exit of image or process". So it might well be the problem is within the image, ifthis RMS bugcheck kills the process.

Mu thought is that if this happens in a top-load period, AND it seems to be something related to RMS, there is some issue in either the DCL code or the image concerning file access. IMHO, date or time are no issues here, assuming your statement that the progream does handle future times properly.

[Willem Grooters]

I read your remark on DCL WAIT when it happened.... Weird, indeed.

[Jon Pinkley]

Rob,

Perhaps you weren't telling us all you knew about the problem at the start to see if anyone could come up with an alternate possibility than what your support organization suggested.

However, now that the RMS BUGCHECK is out of the bag, can you please tell us more?

Timestamps provide good circumstantial evidence that the termination of the GBSINVRUN job and the RMS BUGCHECK were related.

As Hein stated, an RMS BUGCHECK will definitely kill the process that detected the inconsistency.

Was there an RMS BUGCHECK at the time the process in a DCL WAIT was deleted? (BTW, how did you determine that was the state of the process? WAIT is a CLIROUTINE, and as such doesn't have an image associated with it.) What other events are showing up in the errlog?

What changed 3 years ago? Is that when you upgraded to the ES45?

Are you running T4 or some other system data collection software?

Issues caused by lack of proper synchronization are most likely to become evident when the system is busy, so it would not surprise me if the underlying cause is synchronization related. Unfortunately, these are in general not easy problems to debug, as often the detection of the corrupted data isn't discovered until later, and all VMS can do when it finds the inconsistency is to bugcheck. The point being that the process that detects the inconsistency may not be related to the cause. Since you don't want to allow a crash, is there a time that you can stress the system with BUGCHECKFATAL set to 1?

Is there other software involved you are neglecting to tell us about? Are you using RMS Journaling, Rdb, some third party remote journaling or shadowing product, etc. Especially anything that does stuff in exec or kernel mode.

If these are related to Exec mode bugchecks, I am not sure auditing is going to tell you much. Definitely won't hurt,

Jon

[Robert Atkinson]

> how did you determine that was the state of the process

I can see from the batch logfile that the process was at a WAIT statement at the same time the BUGCHECK ocurred.

As far as I'm aware, nothing in particular changed 3 years ago. We we're running HSG80/ES40 when this first ocurred. We copied the system disk over to the new hardware, so if the problem is VMS related, it would have been moved over.

Although it is the end of the year this happens, the system is no busier than at any other point in time. The end of November is our peak processing point, so if it were load related, this is when I'd expect problems.

We have T4 installed, but I'm not sure what data it's collecting.

I checked the timing of the previous errors against this year, and some happen before our yearend processing, and some after, so that seems to rule out a rogue yearend program.

My main query with the group was to see if anyone else had seen anything like this at yearend, which seems to not be the case. I'm glad of everyones input here, especially the audit suggestions, so I'm happy to close this unless anyone would like to make more comments/suggestions?

Rob.

[Jon Pinkley]

Rob,

RE:"I can see from the batch logfile that the process was at a WAIT statement at the same time the BUGCHECK ocurred."

Does that mean that the logfile ended with something like:

$ WAIT 00:05:00

and that was the last line in the file?

Much more conclusive would be if

$ SET PREFIX "(!8%T) "

was in effect and you have something like:

(23:03:18) $ WAIT 00:05:00

and you knew the bugcheck occurred at 23:04:39, i.e. before the wait had expired.

I would not be surprised if the logfile cannot be trusted to have flushed the buffers, because that's an RMS function, and there was an RMS bugcheck. Hein or Volker will know. My point is that I think there is a good possibility that code after the WAIT had completed was actually executing at the time of the Bugcheck.

Is every one of these unexplained process deletion events paired with an RMS Bugcheck?
If so, you really need to try to determine what the cause is. Making the EXEC mode Bugcheck fatal will give you the best chance of being able to determine the cause, but before you do that, make 100% sure your system is setup to be able to save the crash dump. It would be a waste to take the crash but not end up with a valid dump.

RE:"Although it is the end of the year this happens, the system is no busier than at any other point in time. The end of November is our peak processing point, so if it were load related, this is when I'd expect problems."

I was just going by your statement that you couldn't allow an avoidable crash because it was the busiest time of the year. Perhaps it is all the activity in the files at the end of Nov that is causing the files (I am assuming indexed files here) to be badly tuned, although that in itself shouldn't cause a Bugcheck. I am not familiar enough with RMS internals or decoding the errorlog contents to be able to know if anything useful can be obtained from your errorlog entries. Hein was able to derive some info, how much more is possible, I have no idea.

RE: "We have T4 installed, but I'm not sure what data it's collecting."

Having it installed without collecting data is possible, but not very useful. The default collection command procedure will collect a lot of useful info, but the raw data normally gets deleted after a relatively short period, so it is questionable if you still have the raw monitor.dat file.

RE:"I checked the timing of the previous errors against this year, and some happen before our yearend processing, and some after, so that seems to rule out a rogue yearend program."

Well it is possible that the fact these only happen at year end is a coincidence, but I would at least look for something that is triggering the bugchecks.

Is it always the same job that is affected, of just random batch jobs. If more than one job is affected, are there common files the jobs are using?

Jon

[Jan van den Ende]

Robert,

>>>
I can see from the batch logfile that the process was at a WAIT statement at the same time the BUGCHECK ocurred.
<<<

Please DO realise that batch job logs are only flushed ever so often.
A killed job often does NOT get the chance to write the last part of the logfile.

So, concluding that the process deletion happened during WAIT is by no means warranted.

Just my EUR 0,02

Proost.

Have one on me.

jpe

[Robert Atkinson]

Am aware of log flushing - set to 5 seconds on all of our processes anyway - but the termination time and the date/time in the log file coincide to show the process was running a WAIT.

Rob.

[Jon Pinkley]

Rob,

RE:"Am aware of log flushing - set to 5 seconds on all of our processes anyway - but the termination time and the date/time in the log file coincide to show the process was running a WAIT."

Sorry, even though I am not from Missouri, please show me. Where did you get the termination time? My guess is the job completion time from the retained queue info. What do you mean by "date/time in the log file". To me these are both ambiguous.

And quite a lot can happen in 5 seconds.

Jon

[Robert Atkinson]

"Completed 27-DEC-2006 18:50:12.88 on queue BETA$OPERATIONS"

ROB$ type gbsinvrun.log;997
$! RUNNING SYLOGIN.COM
$!
.......
27-DEC:18:48:45> $ DELETE /LOG SYX:TMPLOC.INT;*
%DELETE-I-FILDEL, SY1:[LIVE.DAT]TMPLOC.INT;1 deleted (290 blocks)
27-DEC:18:48:46> $ COPY /LOG SYX:INVTEL.WRK DEV$INTAREA:*.TW3_22J7261
%COPY-S-COPIED, SY8:[LIVE.DAT]INVTEL.WRK;1 copied to DEV$INTAREA_ROOT:[20080122]INVTEL.TW3_22J7261;1 (11281 blocks)
27-DEC:18:48:46> $ DELETE /LOG SYX:INVTEL.WRK;*
%DELETE-I-FILDEL, SY8:[LIVE.DAT]INVTEL.WRK;1 deleted (70035 blocks)
27-DEC:18:48:46> $!
27-DEC:18:48:46> $ WAIT 00:10:00

[Jon Pinkley]

Thanks,

I assume there was also a bugcheck and it had its finger pointed at the DBSINVRUN job?

I have to agree that the log as shown seems to indicate that the process was in a DCL wait at the time.

Is anything throwing Special Kernel Mode AST's at the process? Does DCL have some file open that has RMS global buffers associated (I'm reaching here).

Hein, if you are still reading this thread, do you have any idea how a process could be generating an RMS bugcheck while it is in a WAIT if it isn't related to exec or kernel mode AST's being involved?

Jon