topic FULL LOG INFO FROM POP SERVER DISABLES SERVICE in Operating System - OpenVMS

FULL LOG INFO FROM POP SERVER DISABLES SERVICE

Ana M. García Olivencia — Tue, 03 May 2005 08:06:16 GMT

Hi all.

We have a POP server (AlphaServer ES40, 4 CPUs, $GB memory) and we are interested in collecting information about POP users connected and message-ids downloaded (subject information, not contents).

We have tried defining two logical names:

TCPIP$POP_LOG_LEVEL "THREAD"
TCPIP$POP_TRACE "1"

If we ONLY define the first one (LOG_LEVEL), it gives some of the information needed (users successfully connected and number of messages downloaded, but nothing about message-ids). If we additionally define the second one (TRACE), it gives us a lot of information (more than we need), the number of POP processes increases a lot (logically the POP thread has to do more things for each client connection) and the number of files increases accordingly in size and in number (one file per POP process).

This is not a problem except for the fact that, after determined circunstances (perhaps a peak number of client connections, perhaps a limit reached, we don't know), the POP service is automatically disabled.

Checking the POP logs, the only error message is:

sys$cancel: %SYSTEM-F-IVCHAN, invalid I/O channel"

but this message also appears in old logs where there was no log logical names defined (this could be another topic subject), and during normal service operation.

As the service is disabled there is no way to check if the service limit is reached. And with accounting, the POP processes end as if they were shutdown.

All this happens with the default number of threads (15) per POP process. We have been testing modifing the TCPIP$POP_MAXIMUM_THREADS to values greater and lower than 15, but it is worse.

Has anybody had the same behavour?. Is it necessary to modify some parameters or limits?. Is there another intermediate value (perhaps not documented) for these logical names?. Currently, we only have the TCPIP$POP_LOG_LEVEL defined to THREAD and it works ok.

Thank you very much in advance.

Regards.

Ana Mª García Olivencia
Servicio Central de Informática
Area de Sistemas y Comunicaciones
Universidad de Málaga
Campus Universitario Teatinos
29071 - Málaga
SPA

Re: FULL LOG INFO FROM POP SERVER DISABLES SERVICE

Willem Grooters — Tue, 03 May 2005 08:20:11 GMT

I'm not sure it does apply to your problem, but I found that POP would stop functioning if pgflquo parameter for user TCPIP$POP is too small. It might be that increasing this solves your problem. Probably there are more parameters you need to increase (check *lm parameters)

Have you checked Accounting? It might hold a clue why it stopped (EXQUOTA would point to any of above)

Re: FULL LOG INFO FROM POP SERVER DISABLES SERVICE

Marc Van den Broeck — Tue, 03 May 2005 08:36:08 GMT

I guess you have to increase the channelcnt parameter (sysgen).
We had to increase it from 31 (default) to 4000 (for Oracle).
Use autogen and add min_channelcnt = 4000
to modparams.dat (or use less then 4000)

Re: FULL LOG INFO FROM POP SERVER DISABLES SERVICE

Ana M. García Olivencia — Tue, 03 May 2005 08:39:38 GMT

As I said in the problem description, checking the accounting, the POP process ends as if POP was shutdown in the normal way.

With respect to the PGFLQUO quota, there is no message about it but, if I am not mistaken, the pgflquo value resets for each new POP process created, and there is no message about it neither in the POP logs nor in the accounting.

Thanks

Ana

Re: FULL LOG INFO FROM POP SERVER DISABLES SERVICE

Marc Van den Broeck — Wed, 04 May 2005 02:56:40 GMT

Ana,

have you tried to change the channelcnt parameter as I suggested?

Rgds
Marc

Re: FULL LOG INFO FROM POP SERVER DISABLES SERVICE

Ana M. García Olivencia — Wed, 04 May 2005 03:39:27 GMT

Marc.

The current value for CHANNELCNT is 4096.

Before doing the tests we had some parameters changes pending (it is a production system):

Parameter Current Value New value
MAXPROCESSCNT 522 731
GBLPAGES 6682157 6734296
LOCKIDTBL 12000 12512
RESHASHTBL 16384 32768
NPAGEDYN 65093632 65100000
PAGEDYN 7602176 10305536

We executed AUTOGEN before and after the POP tests and, comparing both reports, there were no differences.

Supposing this would have been the reason, I think that the POP process would have finished with some error relationed to the parameter involved or some errors in OPERATOR.LOG. Anyway, as soon as we can, we'll change the parameters.

Is there a way with TCP/IP to record or to log whatever happens to a service?

Thanks.

Ana

Re: FULL LOG INFO FROM POP SERVER DISABLES SERVICE

Ian Miller. — Wed, 04 May 2005 04:14:08 GMT

have you monitored the process quota use of the server to check for a quota problem?

Re: FULL LOG INFO FROM POP SERVER DISABLES SERVICE

Ana M. García Olivencia — Wed, 04 May 2005 08:30:12 GMT

Ian.

We have been testing again and we have found the following:

- If we reduce the number of threads per POP process (for example, 5) and enable both logical names, the TCPIP$POP PRCLM limit is reached (it was 10; now we incremented to 100) and the service is disabled.

- Assuming the default number of threads per POP process (15), we have seen that even only enabling TCPIP$POP_TRACE to 1, the service starts ok, it works for a while but there is one moment that the service doesn't respond to a "telnet node 110" and the POP clients receive a socket error. In that circunstance:
* The service is not disabled, is up but not responding.
* The number of POP processes created has been 5.
* The "peak" value of the POP service has been 25.
* The only error messages appearing in the last POP log are:
....
read iosb: %SYSTEM-F-CONNECFAIL, connect to network object timed-out or failed
read iosb: %SYSTEM-F-LINKDISCON, network partner disconnected logical link
....
(they repeat a lot but they are not the last messages written to the log).

The TCPIP$POP account quotas are:

Maxjobs:100 Fillm:300 Bytlm: 250000

Maxacctjobs: 0 Shrfillm:10 Pbytlm:0
Maxdetach:0 BIOlm:200 JTquota:8192 Prclm:100 DIOlm:200 WSdef:350

Prio:8 ASTlm:250 WSquo:512

Queprio:5 TQElm:100 WSextent: 20000

CPU:(none) Enqlm:4000 Pgflquo: 1000000

Perhaps we are reaching a TCPIP limit (parameters from sysconfig). Is there a way to log some debugging information about TCPIP?

Regards and thanks.

Ana

Re: FULL LOG INFO FROM POP SERVER DISABLES SERVICE

Ian Miller. — Wed, 04 May 2005 08:53:16 GMT

could you monitor the pop server process using SHOW_QUOTA.COM
http://dcl.openvms.org/stories.php?story=03/06/03/0022504

or AMDS or Availmgr?
I still suspect its running out of something.

Re: FULL LOG INFO FROM POP SERVER DISABLES SERVICE

Jan van den Ende — Wed, 04 May 2005 09:03:33 GMT

Ana,

I have no experience with POP whatsoever, and I am just guessing now. But your kind of problem DOES ring a bell somewhere.

First, are those POP processes Network processes (in $ SHO SYS, do they have an "N" at the end of the line?).
If not, then I am hearing the wrong bells.
But, if they ARE network processes, then what is your SYSGENvalue for NJOBLIM?
It is dynamic, you can increase it on the fly. (btw, it is obsolete starting V8.2).
We had something similar long ago on X25 connections, but it took us a long time to find THIS limit!

HTH.

Proost.

Have one on me.

jpe

Re: FULL LOG INFO FROM POP SERVER DISABLES SERVICE

Ana M. García Olivencia — Thu, 05 May 2005 04:41:10 GMT

Ian.

I have the procedure prepared to use it when doing the tests .

Jan.

The TCPIP$POP processes are network processes and the NJOBLIM parameter is currently 16. Perhaps, this could be the reason. But, what is it really limiting this parameter?. In this moment, with POP working ok, when I execute SHOW SYS/NETWORK, there are more than 16 network processes and nobody has complained.

If the limit resets to each new TCPIP$POP process created, I think this limit is not reached because the POP process works with threads, not subprocesses (each new POP process is a new job). However, if the limit is shared by all TCPIP processes (TCPIP account), it is very possible we are reaching the limit.

I have been searching for information about the limit, but I haven't found more than the definition.

As soon as I can do more tests I'll let you know (remember, it's a production system).

Thanks all.

Regards.

Ana

Re: FULL LOG INFO FROM POP SERVER DISABLES SERVICE

Jan van den Ende — Thu, 05 May 2005 05:54:12 GMT

Ana,

sounds all the more like it might be the same!

We also could not nail it down exactly. (maybe one of the more Internals literate guru's).
... and setting NJOBLIM much higher (we squred it -> 256) does cost only a VERY small amount of memory. And it can be done with no risk at all on a running system.
Even if it is not the solution, it is a very cheap try.

Anyway, this limit has been removed with the advent of V 8.2 (but then, most systems, certainly Production, will not be running that coming soon, me thinks).

Hope you strike lucky!

Proost.

Have one on me.

jpe

Re: FULL LOG INFO FROM POP SERVER DISABLES SERVICE

Ana M. García Olivencia — Thu, 05 May 2005 07:34:47 GMT

Ian, Jan.

I have raised NJOBLIM parameter to 512 and defined only TCPIP$POP_TRACE to 1 (it writes ALL the POP server-client dialogue).

I have monitored with SHOW_QUOTA.COM the POP processes created and there is no lack of resources. The peak service limit is not very high when the problem happens.

The problem is that a telnet to port 110 doesn't answer or answers very late, although the POP process/es continues working (they are not stalled or hung). It seems that the fact of writing a lot of information in the log (take into account that all the mail contents are written) impacts on the POP process behavour and performance. Or perhaps, as I mentioned in a previous reply, there is a TCPIP parameter that it's being reached.

Has anybody any suggestions?. On our behalf, we are going to upgrade to V8.2 as soon as possible and see how it works there.

Thank you very much

Ana

Re: FULL LOG INFO FROM POP SERVER DISABLES SERVICE

Ian Miller. — Thu, 05 May 2005 09:13:11 GMT

parhaps the writing to a log file is done in a way which holds up all the other threads while it is writing. Just as an experiment try putting the log file on a RAM disk or even the nill device (e.g. set log file name to NL:POP.LOG)and see if the performance improves.

The log file writing used to be done using a simple fprintf - I don't know how that works now (last source I saw was early V2.0 of the public IUPOP3).

Re: FULL LOG INFO FROM POP SERVER DISABLES SERVICE

Ana M. García Olivencia — Fri, 06 May 2005 08:36:41 GMT

Ian.

It's not easy to change the log file to the POP server (at least, I don't find any qualifier to change it at UCX SET SERVICE POP level).

A few months ago, when we faced to this problem when trying to put the log in another disk, the only thing it worked was to define the default device and directory of the TCPIP$POP account with the new location.

Following the same approach (in this case, I have tested in a development system), I have defined the device field of the account to NL: and, although it seems that the service starts ok, it is immediately disabled (when it receives the first connection).

The RAM disk test is not possible, by the moment.

Thanks.
Have a good weekend.

Regards.
Ana

Re: FULL LOG INFO FROM POP SERVER DISABLES SERVICE

Ana M. García Olivencia — Thu, 20 Apr 2006 02:51:38 GMT

Sorry for not closing the thread before.

We have solved our log needs defining only the logical name TCPIP$POP_LOG_LEVEL to "THREAD". With the information it reports, we can track the messages and the POP commands executed by a user.

Regards.

Ana