Chuck,
That was it. I only needed the DEBUG T1 (not a subsequent command, they must have fixed the APAR SE27332 problem - in 7.1 at least.
FTP session was still active after 76 minutes when the rmvlnk finished, and the following "quote rcmd DSPJOBLOG" did create a job log on the server.
Here's the output log file from the batch FTP when I reran (just the last [part of the log):
bin
200 Representation type is binary IMAGE.
Enter an FTP subcommand.
quote rcmd LODIMGCLG VIRTUALTAP OPTION(*UNLOAD) DEV(TAPVRT01)
250 Command LODIMGCLG VIRTUALTAP OPTION(*UNLOAD) DEV(TAPVRT01) successful.
Enter an FTP subcommand.
DEBUG T1 7200
Client T1 time value set to 7200 seconds.
Enter an FTP subcommand.
quote rcmd rmvlnk '/asp02/virtualtape/VOL001'
250 Command rmvlnk '/asp02/virtualtape/VOL001' successful.
Enter an FTP subcommand.
quote rcmd DSPJOBLOG
250 Command DSPJOBLOG successful.
Enter an FTP subcommand.
quit
221 QUIT subcommand received.
Neil Palmer, Waterloo, Ontario, Canada
(This account not monitored for personal mail,
remove the last two letters before @ for that)
________________________________
From: Neil Palmer <neilpalmer400mr@xxxxxxxx>
To: Midrange Systems Technical Discussion <midrange-l@xxxxxxxxxxxx>
Sent: Sunday, October 6, 2013 9:22:48 PM
Subject: Re: SAVSYS to IMGCLG then to DVD on PC
Chuck,
Correct, the original timeout is not 75 minutes. That's how long the RMVLNK takes.
The FTP session times out between 5 & 10 minutes after issuing the RMVLNK.
That fits in with the 300 seconds for INACTTIMO on the CHGFTPA as the help says it may take up to an additional 120 seconds to end the session.
Of course the RMVLNK command will finish executing on the target system so it doesn't really matter. Still, I thought TIME would have kept it active. I'll do a bit more testing and maybe open a PMR with IBM to see if the INACTTIMO value is what TIME should change on the server side (or maybe it's the client side that is terminating the connection?).
When the RMVLNK finishes it won't execute any more commands as the FTP session is gone, so I just made sure RMVLNK was the last thin I needed to run, then it doesn't matter.
Interesting that APAR SE27332 lists applicable releases as R520, R530, 5.4, 9.9.9
I wonder if that 9.9.9 is someone's hint that this isn't going to be fixed?
Though the text does say this will be fixed next release, and the last proper release mentioned was 5.4 - so one would be led to believe that it is fixed in 7.1 (in this case both source & target systems are 7.1 at cume level 13037).
I tested the
> DEBUG T1 6900
Client T1 time value set to 6900 seconds.
and from the text for the reply message above it appears I may ONLY need the DEBUG T1 in my FTP command file.
I will test that tonight:
Message ID . . . . . . : TCP3CA8 Severity:. . . . . . . : 0
Message . . . . : Client T1 time value set to 6900 seconds.
Cause . . . . . : This message displays the current value of the FTP client
time-out limit for reading replies from the FTP server.
Recovery . . . : For further information about setting this time-out
value, type 'HELP DEBUG' and press enter.
Technical description . . . . . . . . : This time-out limit is initially
set to 600 seconds when the FTP client session is started.
When the server does not return a reply within this time limit, the
client closes the connection to the server.
PS - the FTP is not performed interactively.
The text was copied directly from the FTPOUTPT file that the messages were redirected to.
That file does contain the "Enter an FTP subcommand." lines.
The backup program submits this job:
SBMJOB CMD(FTPBATCH RMTSYSTEM(SYSTEM52) +
FTPFILE(FTPBATCH) FTPFLIB(QGPL) +
FTPMBR(DLTVIRTAPE)) JOB(DLTVIRTAPE) +
JOBQ(VIRTUALTAP) LOG(4 0 *MSG) LOGCLPGM(*YES)
The FTPBATCH command is:
FTP BATCH (FTPBATCH)
Type choices, press Enter.
Label . . . . . . . . . . . . .
Remote System . . . . . . . . . RMTSYSTEM > SYSTEM52
FTP Script File . . . . . . . . FTPFILE > FTPBATCH
FTP Script Library . . . . . . . FTPFLIB > QGPL
FTP Script File Member . . . . . FTPMBR > DLTVIRTAPE
Library . . . . . . . . . . . . FTPPLIB *NONE
The FTP command source member is:
rstprofile **********
namefmt 1
bin
quote rcmd LODIMGCLG VIRTUALTAP OPTION(*UNLOAD) DEV(TAPVRT01)
quote time 7200 7000
quote rcmd rmvlnk '/asp02/virtualtape/VOL001'
quote rcmd DSPJOBLOG
quit
(the "quote rcmd DSPJOBLOG" was just added as a test to see if the session is still active after the "quote rcmd rmvlnk..." completes).
The output log file in its entirety contains (note the second 220 response):
Output redirected to a file.
Input read from specified override file.
Connecting to host System52 at address 999.999.999.999 using port 21.
220-QTCP at SYSTEM52.
220 Connection will close if idle more than 5 minutes.
Enter login ID (qsecofr):
331 Enter password.
230 RSTPROFILE logged on.
OS/400 is the remote operating system. The TCP/IP version is "V7R1M0".
250 Now using naming format "0".
257 "QGPL" is current library.
Enter an FTP subcommand.
namefmt 1
250 Now using naming format "1".
Server NAMEFMT is 1.
Client NAMEFMT is 1.
Enter an FTP subcommand.
bin
200 Representation type is binary IMAGE.
Enter an FTP subcommand.
quote rcmd LODIMGCLG IMGCLG(VIRTUALTAP) OPTION(*UNLOAD) DEV(TAPVRT01)
250 Command LODIMGCLG IMGCLG(VIRTUALTAP) OPTION(*UNLOAD) DEV(TAPVRT01)
successful.
Enter an FTP subcommand.
quote time 7200 7000
250-File transfer time-out value set to 7000 seconds.
250 Inactivity time-out set to 7200 seconds.
Enter an FTP subcommand.
quote rcmd rmvlnk '/asp02/virtualtape/VOL001'
No response from remote host; all connections closed.
Enter an FTP subcommand.
quote rcmd DSPJOBLOG
You must first open a connection.
Enter an FTP subcommand.
quit
Neil Palmer, Waterloo, Ontario, Canada
(This account not monitored for personal mail,
remove the last two letters before @ for that)
________________________________
From: CRPence <CRPbottle@xxxxxxxxx>
To: midrange-l@xxxxxxxxxxxx
Sent: Sunday, October 6, 2013 3:51:16 PM
Subject: Re: SAVSYS to IMGCLG then to DVD on PC
On 04 Oct 2013 18:00, Neil Palmer wrote:
In CHGFTPA it is INACTTIMO(300)
Hmmm... That makes the origin of the apparent 75 minutes, as the
timeout being experienced, all the more confusing.
But then... the RMVLNK is said to take ~75 minutes; i.e. "I'd need
about 75 minutes for the RMVLNK to complete." That, along with my
further review of the described processing and described failure, and
with some testing of effectively equivalent [in time] processing, I am
confident the issue encountered will be resolved by including in the
processing, the following two FTP requests at the beginning of the
script [before or after the QUOTE TIME 7200]. Note: the second request
is the implementation of a circumvention to a defect [APAR SE27332; link
in my prior reply] that may or may no longer exist, but causes no harm
if included:
DEBUG T1 7200
PWD
The remaining comments are for the archives to further understand my
presumptive conclusion, and to provide specific responses to additional
remaining comments in the quoted\replied-to message.
I thought that's what the TIME would change on the Server
It is. The "QUOTE TIME <inactivity> <transfer>" invocation should
override the inactivity-timeout and the transfer-timeout, in seconds, at
the server.
(didn't think it would matter on Client side),
Correct. The QUOTE TIME is only relevant to the server.
but maybe I also need a TIME in addition to the QUOTE TIME ?
There is no client TIME subcommand :-( Achieving the same effect on
the client, is effected via the less obvious "DEBUG T1 <inactivity>"
request; i.e. sets the inactivity-timeout, in seconds, at the client.
Along those lines, I wondered /aloud/ in my prior reply, if perhaps
adding the FTP subcommand request to DEBUG T1 7200 would provide relief;
albeit, possibly requiring the circumvention from the APAR, which is to
follow the DEBUG T1 request with the PWD request. I will explain below,
why I think this client-side inactivity-timer may be the source of the
problem, and thus *enabling resolution* to the issue being encountered.
Sorry for confusion - I had edited down the FTP log
Yet I should have recognized, having seen the text "Enter an FTP
subcommand." at each step, that the FTP was being performed
interactively. Of course *now* it is obvious to me :-)
FWiW:
Normally there is a "220" prefixed feedback message TCP12AF from the
IBM i as FTP server, presented in the client session _upon_ connection,
that identifies the inactivity-timeout per "Connection will close if
idle more than ?? minutes." Do these connections say "5 minutes.",
reflecting the INACTTIMO(300)?
Additionally, the request to QUOTE HELP should divulge the inactivity
timer setting that the server has established. The feedback comes in
one of many messages TCP12AF with "214-" prefix that reveals the
inactivity-timeout in seconds: "If this connection is not used more than
???? seconds, the session will end."
Finally, the DEBUG T1 without any argument passed for the
inactivity-timer, will feedback TCP3CA8 "Client T1 time value set to ???
seconds."
- the actual end <ed: of the interactive FTP session> was:
Enter an FTP subcommand.
≥ quote time 7200 7000
250-File transfer time-out value set to 7000 seconds.
250 Inactivity time-out set to 7200 seconds.
The "250" prefixed TCP12AF messages are an indication that the server
had received and supposedly had activated the requested override, in
this case, to both the transfer-timeout and the inactivity-timeout. As
noted above, the QUOTE HELP should reflect that change in its feedback.
However, noting the oddity of the referenced APAR\defect [from my
prior reply], and its circumvention, I wondered /aloud/ also, if perhaps
issuing the FTP subcommand PWD, after the QUOTE TIME 7200 7200, and
before passing the next QUOTE text to the server... might be required to
circumvent a similar issue whereby the feedback from the server was an
effective lie; i.e. perhaps the override does not go into effect unless
the first request after the QUOTE TIME invocation is *not* another QUOTE
subcommand. I have since decided that was just a misguided inference,
based on my concentrating too much on the ~75 minutes as an /apparent/
timeout at the /remote server/ instead of understanding what is really
happening; i.e. the timeout was distinct from the ~75 minutes for the
QUOTE RCMD RMVLNK to complete. Again... explained later\below in my reply.
While testing on a v5r3 system, with a variety of chosen server
inactivity-timeout values, I would follow the QUOTE TIME with some QUOTE
RCMD DLYJOB seconds_value requests [rather than using RMVLNK] to verify
that the inactivity setting was being honored. To minimize time
requirements for any individual test-case, of course my choices for the
seconds_value were /smallish/ rather than something like 100+ minutes.
But I had noticed some longish tests with QUOTE RCMD DLYJOB 600 that
would experience an occasional failure: TCP3C6B "No response from remote
host; all connections closed." In each failing scenario however, the
server request actually completed, irrespective my inference of the
meaning for that message; i.e. my interpretation was that the /remote
host/ had closed the connection. The message says however, that the
problem was due to no response being "received from the remote host
within the timeout period." Thinking on this...
I recalled never having experienced overrides to the server's
inactivity-timer being non-functional [through v6r1]; i.e. never having
received an unexpected timeout, after issuing the QUOTE TIME to avoid a
timeout. I often had performed long and complex processing in FTP
scripts having issued an earlier QUOTE TIME request, usually somewhat
long-running CALL PGM() requests via FTP subcommand QUOTE RCMD requests
in my scripts, after which the parsed\reviewed standard output revealed
no errors were encountered. But after additionally reviewing some
documents from some web searches, in conjunction with results of my
recent testing, I have concluded that I must have always included the
client-side timer update [i.e. "DEBUG T1 inactivity" requests] when
using homogeneous FTP. I apparently had forgotten about using that
client-side request, probably because I typically just copied from a
base-source and since for several years, my only FTP work to an IBM i
server has been from non-i clients... apparently those clients have a
sufficiently long client inactivity timeout setting, that I had not
noticed an issue.
Enter an FTP subcommand.
≥ quote rcmd rmvlnk '/asp02/virtualtape/VOL001'
No response from remote host; all connections closed.
I am fairly confident that what happens, as I infer... Rather than
the long-running request at the server having been diagnosed as
exceeding its inactivity timer and thus the connection being closed,
only after control returns to the client from the QUOTE RCMD request,
the client detects that its own inactivity-timer has been exceeded.
Then the client closes the connection, but diagnoses the effect the same
as if the /remote host/ had terminated the connection; a somewhat
confusing effect, for a timeout at the server versus for a timeout at
the client... being indistinguishable.
It would be nice, for example, if there were two messages used
instead of just the one TCP3C6B. Perhaps one would suggest that the
issue was per "No _response_ was received _from_ the remote host within
the *client inactivity* timeout period." Perhaps another would suggest
that the issue was per "No _request_ was received _at_ the remote host
within the *server inactivity* timeout period." Or perhaps the text of
that message could be expanded to be explicitly clear that there are
*two* inactivity timers that may have effected the closed connection,
and in the recovery, to show the syntax for setting both timers.
From what I can infer from my testing, the RMVLNK will have completed
irrespective of where there is an inactivity timeout; client or server.
It seems that a long-running request is not terminated by the
inactivity-timer at the IBM i FTP server. Instead it seems, only a
delay _between requests_ reaching the server will effect close of the
connection; i.e. a delay that exceeds the inactivity-timer setting for
the server. I was actually under the false impression that the timer
would terminate the active request at the server... and the joblog would
show the request being interrupted. And unlike some other FTP clients,
the IBM i client seems not to terminate the connection until the control
returns from a QUOTE subcommand; i.e. even with a very small client
inactivity timeout, the IBM i FTP client will allow the server to
continue processing whatever active request that was sent via the QUOTE
subcommand.
Enter an FTP subcommand.
≥ quit
I'll add the QUOTE RCMD DSPJOBLOG and see what that reveals.
Regardless of what may have seem implied by my prior reply... That
request can not assist; it will not function in _this_ scenario :-(
Apologies for having shown that particular request in my prior reply,
instead of PWD or something else. It was just meant to be any request
that would appear before an EOF was encountered, and something before a
QUIT, just in case that did not appear in the stdout... but that is all
moot, because this was not a scripted request [my misunderstanding,
whereas instead, it was an interactive FTP session].
The /connections closed/ implies that there is no ability to send any
more requests via that session; i.e. QUIT is possible to terminate the
FTP client session command-line, and the OPEN could be issued to start a
new session at the server, but no further request that communicates
to\with the server will be possible within that client session. Either
the documented CHGJOBD request would need to be done to force logging to
occur, or perhaps early in the session, having issued the request to
QUOTE RCMD CHGJOB LOG(4 0 *SECLVL) would be similarly effective.? The
latter seemed not to assist in my testing... and I do not have the
required authority to activate the logging via the job description on
the system where I test.
midrange.com
