Wazi aaS: クラウド上でのメインフレーム開発環境構築 - (7)' Wazi Image Builder - Trouble Shootingメモ

Last updated at 2024-05-11Posted at 2024-02-29

はじめに

とある環境でWazi Image Builderを使用して既存のオンプレz/OS環境からIBM Cloud環境への移植を行いました。その際に発生した主要な問題とその時の対応方法を参考までに整理しておきます。
※環境依存の状況もあるかと思いますので当記事に記載した対応方法がすべての環境で適用できるとは限りません。あらかじめご了承願います。

発生事象/対応措置例

Case1: RACF DASDVOLクラス権限

事象

WIBコンソールから"コンポーネントの作成"を行った際にエラーが発生。
VOLの一覧はWIBコンソール上で表示できてきており、コンポーネントとして抽出したい対象のVOLを選択してコンポーネントの作成を実行すると、指定したVOLUMEの抽出に軒並み失敗。
(VOLの一覧がWIBコンソール上で表示されていたので、Extraction Utilityは動いていると言える。)

調査/確認

WIBサーバーの実体であるLibertyのログ(/opt/ibm/wib/wib-server/logs/messages.log)を確認すると各VOLの抽出の際にDASDVOLの権限に関してこんな感じのメッセージが出ていた。

com.ibm.zdt.handler.PipingDataTransferHander   E [ZDT-LOG-ERROR] Extracting volume VOL001 for component Component[name=z25sys1,version=1,source system=SourceSystem[label=Z25A,hostname=xxx.xxx.xxx.xxx,port=22,type=SYSTEM TYPE Z]]: failed on executing commmand _BPXK_JOBLOG=STDERR /usr/lpp/IBM/zdt/feuc image 'VOL001''/home/zwazit/extraction_pipe.nnnnnnnnnnnnn' compress with return code 10 and error message: 
stdout: HH:MM:SS.SS zD&T data migration   20230718-121810710
 16:28:25.91 Access to DASDVOL VOL001 not granted: RACROUTE RC=4
 ,stderr:<empty>

※この時、ソース環境のz/OSのSYSLOGには特にRACF関連のメッセージは出力されていないのが非常に分かりにくい。

z/OS側の状況としては、DASDVOLクラスがアクティベートされていたが、プロファイルが全く存在していない状態だった。

参考

Wazi aaS - Creating a volume component

If you create a volume component, grant READ access to the SAF profile in class DASDVOL for the volumes that are extracted to the user ID that is used in the Wazi Image Builder. For more information about DASD volume migration, see section 15.3.2 "RACF® requirements" in the zPDT® Guide and Reference.

Redbook - ISV IBM zPDT Guide and Reference

15.3.2 RACF requirements
The server program requires RACF class DASDVOL to be active and the server program must have at least READ access to all volsers to be transferred. You must determine whether the DASDVOL class is active and used on the system where you install the migration utility server. You can do this task by logging on to TSO with a user ID with RACF SPECIAL authority and issue these TSO commands from a READY prompt or ISPF option 6:
SETROPTS LIST (Check the list of active classes.)
RLIST DASDVOL * (See whether any profiles are defined.)
If these checks are negative, you can assume that the DASDVOL class is not being used.

DASDVOL not in use
The next step is to decide whether only certain volumes should be subject to copying by this migration utility or whether all volumes might be accessed for migration. If you decide to allow migration of all volumes, enter these TSO commands:
SETROPTS CLASSACT(DASDVOL) (Activate the DASDVOL class.)
SETROPTS RACLIST(DASDVOL) (Optional, but recommended here.)
RDEFINE DASDVOL ** UACC(ALTER) (Allow universal alter access.)
SETROPTS RACLIST(DASDVOL) REFRESH (If you RACLISTed the class.)
The DASDVOL class is used only by a selected group of utility programs, such as dump or restore. Allowing UACC(ALTER) does not open all your data sets to access by all users.
Whatever RACF data set protection that you have in place (through the ADDSD and PERMIT commands) is still effective.
This setup is the extent of the RACF setup if DASDVOL was not initially active and you want to allow the migration server to access any volume. If you want to limit the volumes that are subject to migration, you should work with an experienced RACF administrator. The general
technique is to restrict global access to DASDVOL (perhaps with a UACC(NONE) condition) and then issue PERMIT commands to cover the volumes that you want to migrate. For example:
PERMIT VOL123 CLASS(DASDVOL) ID(IBMUSER) UACC(READ)
PERMIT ADCD* CLASS(DASDVOL) ID(IBMUSER) UACC(READ)
SETROPTS RACLIST(DASDVOL)REFRESH (If you RACLISTed DASDVOL.)

In this example, volser VOL123 and any volser beginning with Application Development Controlled Distribution (ADCD) can be accessed by the migration utility.
The usage of the DASDVOL class might have side effects on other utility programs. If DASDVOL was not active before your migration activities, you might want to deactivate it when the migration activities are completed:
SETROPTS NORACLIST(DASDVOL)
SETROPTS NOCLASSACT(DASDVOL)

DASDVOL in use
If you find that the DASDVOL class is active on your server system, discuss the situation with the system programmers that manage that system. Your requirements are simple: you (meaning the user ID who runs the migration server program) need DASDVOL with READ access to whatever volsers that you intend to migrate.

対応措置

総称プロファイル(**)にALTER権限付与することで解決。

コマンド例:

RDEFINE DASDVOL ** UACC(ALTER) AUDIT(ALL(READ))

Case2: IBM Cloudリソース・アクセス権限

事象

WIB管理コンソール上で、ターゲット環境の設定を行う際に問題が発生。

ターゲットとなるIBM Cloudの情報を設定する画面で、APIキーを入力して接続をクリック => 接続OK
プルダウンからリソース・グループを選択 => OK
Cloud Object Storageインスタンスを選択するためにプルダウンメニューを表示 => リストが表示されず選択できない!

調査/確認

WIBサーバーのLibertyのログを見てもエラーは出力されていなかった。当該APIキーを生成したユーザーでIBM CloudにログインしてICOSインスタンスを確認すると、存在が確認できる状態(リストされる)。
※どこにもエラーメッセージらしきものが表示されないので問題判別が困難!

参考

IBM Cloud - Resource Controller - Get a list of all resource instances

恐らく内部的にはリソース・コントローラーに対してGET /v2/resource_instancesこちらのREST APIを発行してICOSインスタンスのリストを取得しようとしていると思われる。
そのためには、上のリンクに記載されている通り resource-controller.instance.retrieve の権限が必要。

対応措置

API Keyを発行したユーザーが属するグループのポリシーを編集し、ICOSのサービスに対して"プラットフォーム・アクセス"のビューワー権限を付与した。

上のチェックを付けることで、resource-controller.instance.retrieve の権限が付与されることになるものと思われる。

その後リトライしたところ、ICOSインスタンスのリストがプルダウンに表示されるようになった。

Case3: gzファイル破損

事象

WIB管理コンソール上でイメージのデプロイ処理を行った時にエラーで失敗。
terraform apply処理でエラー。
デプロイ処理では、内部的にterraformの機能が使用されIBM Cloud上にデータ加工用の仮想サーバー(Linux)を一時的に作成し、そこでCloud initという仕組みを利用して"data mover"と呼ばれるPython Programを実行しデータの加工を行っている。この処理の途中でエラーが発生した。

調査/確認

WIBサーバーのterraformのディレクトリ下(<wib_install_path>/wib-server/terraform/)に、一時的に作成された仮想サーバーにSSHでアクセスするためのprivate keyが作成されている(private_key)。これを使用することで、rootユーザーでこの仮想サーバーにアクセスすることが可能。
作成された仮想サーバーの浮動IP(FloatingIP)をIBM Cloudのコンソールから確認し、scpにて仮想サーバー上のCloud init関連のログ・ファイルを取得する。

コマンド例:

scp -i <wib_inst_path>/wib-server/terraform/private_key root@<floating ip of the temporary VSI>:/var/log/cloud*.log /tmp

※terraformのapplyで失敗すると、その後一時的に作成されていた各種IBM Cloud上のリソースがterraform destroyにより破棄されてしまう。破棄される前に上のコマンドを投入しないと資料が取得できないので注意！

仮想サーバー内の/va/log/cloud-init.log および /var/log/cloud-init-output.log を確認する。

一時的に作成された仮想サーバー内の /var/log/cloud-init-output.log を確認すると、以下のようなエラーで"data mover"(Python)が終了していた。

...

Fetch VOL006 gzip volume from COS and uncompress to /volumes/data/VOL006
Retrieving item from bucket: icos-bkt, key: VOL006_2024-02-19_22_33_54.gz
Retrieving bucket contents from: icos-bkt
Done fetching VOL001 to /volumes/data/VOL001
Done fetching VOL002 to /volumes/data/VOL002
Fetch VOL007 gzip volume from COS and uncompress to /volumes/data/VOL007
Retrieving item from bucket: icos-bkt, key: VOL007_2024-02-19_22_35_16.gz
Retrieving bucket contents from: icos-bkt
Done fetching VOL004 to /volumes/data/VOL004
Fetch VOL008 gzip volume from COS and uncompress to /volumes/data/VOL008
Retrieving item from bucket: icos-bkt, key: VOL008_2024-02-19_20_44_28.gz
Retrieving bucket contents from: icos-bkt
Done fetching VOL005 to /volumes/data/VOL005
Fetch VOL009 gzip volume from COS and uncompress to /volumes/data/VOL009
Retrieving item from bucket: icos-bkt, key: VOL009_2024-02-19_19_52_57.gz
Retrieving bucket contents from: icos-bkt
Done fetching VOL006 to /volumes/data/VOL006
Fetch VOL010 gzip volume from COS and uncompress to /volumes/data/VOL010
Retrieving item from bucket: icos-bkt, key: VOL010_2024-02-19_20_07_42.gz
Retrieving bucket contents from: icos-bkt
Done fetching VOL007 to /volumes/data/VOL007
Done fetching VOL008 to /volumes/data/VOL008
Done fetching VOL009 to /volumes/data/VOL009
Done fetching VOL010 to /volumes/data/VOL010
multiprocessing.pool.RemoteTraceback: 
"""
Traceback (most recent call last):
  File "/usr/lib/python3.8/multiprocessing/pool.py", line 125, in worker
    result = (True, func(*args, **kwds))
  File "/usr/lib/python3.8/multiprocessing/pool.py", line 48, in mapstar
    return list(map(*args))
  File "./data_mover.py", line 204, in get_volume_file
    shutil.copyfileobj(f_gzip, f_out)
  File "/usr/lib/python3.8/shutil.py", line 205, in copyfileobj
    buf = fsrc_read(length)
  File "/usr/lib/python3.8/gzip.py", line 292, in read
    return self._buffer.read(size)
  File "/usr/lib/python3.8/_compression.py", line 68, in readinto
    data = self.read(len(byte_view))
  File "/usr/lib/python3.8/gzip.py", line 479, in read
    if not self._read_gzip_header():
  File "/usr/lib/python3.8/gzip.py", line 427, in _read_gzip_header
    raise BadGzipFile('Not a gzipped file (%r)' % magic)
gzip.BadGzipFile: Not a gzipped file (b'l\x89')
"""

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "./data_mover.py", line 324, in <module>
    data_volumes = p.map(get_volume_file, volumes)
  File "/usr/lib/python3.8/multiprocessing/pool.py", line 364, in map
    return self._map_async(func, iterable, mapstar, chunksize).get()
  File "/usr/lib/python3.8/multiprocessing/pool.py", line 771, in get
    raise self._value
gzip.BadGzipFile: Not a gzipped file (b'l\x89')
Cloud-init v. 23.3.1-0ubuntu1~20.04.1 running 'modules:final' at Tue, 20 Feb 2024 05:59:46 +0000. Up 18.28 seconds.
2024-02-20 06:22:25,254 - cc_scripts_user.py[WARNING]: Failed to run module scripts_user (scripts in /var/lib/cloud/instance/scripts)
2024-02-20 06:22:25,255 - util.py[WARNING]: Running module scripts_user (<module 'cloudinit.config.cc_scripts_user' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_scripts_user.py'>) failed
Cloud-init v. 23.3.1-0ubuntu1~20.04.1 finished at Tue, 20 Feb 2024 06:22:25 +0000. Datasource DataSourceNoCloud [seed=/dev/vdc][dsmode=net].  Up 1377.36 seconds

エラーの出方が恐ろしく不親切。
どうやらz/OSから吸い上げたVolumeのファイル(*.gz)を解凍しようとしたときに、ファイルが壊れていて解凍に失敗したらしい、ということがなんとなく読み取れる。しかし、どのファイルの解凍に失敗したのかがメッセージからすぐに分からない。
前段のメッセージを見ていると、各VOLファイルごとに、以下のメッセージがセットで出ているらしいことが分かる。

Fetch VOL010 gzip volume from COS and uncompress to /volumes/data/VOL010
Retrieving item from bucket: icos-bkt, key: VOL010_2024-02-19_20_07_42.gz
Retrieving bucket contents from: icos-bkt
Done fetching VOL010 to /volumes/data/VOL010

そこで、以下の2つのメッセージを抜き出して比較し、Fetch開始されているが完了していないVOLを抜き出せば、そのファイルが壊れている可能性が高いというあたりをつけることができる。
Fetch <VOL> ...
Done fetching <VOL> ...

対応措置

上であたりをつけたVOLをz/OSから抽出しなおしてデプロイ処理をリトライすると、エラーは発生せずにデプロイが正常に完了した。
ファイルが壊れた根本原因は不明。Extraction Utilityがgzファイルをうまく作成できなかったか、z/OS => sftpサーバー => ICOSの転送の際にファイルが壊れたか...。
同じことを繰り返せばうまく動くというのはあまりうれしい話では無いのだが。まぁレアケースを踏んだと思うことにしよう。

Case4: 通信装置アドレス数の制約

事象/調査/確認

イメージのデプロイ時にICOS上に生成されたdevmapファイルの中身を確認すると、OSA関連のデバイスの定義に不備があることが確認された。

# This file was generated at 20230529_014645 -0400

[system]
processors	0
memory	4000m
ipl	0A80	"0A82K2"
3270port	3270
system_name	DEFSYS

[manager]
name	aws3274	0001	#define a few 3270 terminals 
device	0700	3279	3274	tso
device	0701	3279	3274	tso
device	0702	3279	3274	tso
device	0703	3279	3274	tso
device	0704	3279	3274	tso

[manager]
name	awsosa	0002	--path=A0	--pathtype=OSD	--tunnel_intf=y	--tunnel_ip=172.26.1.1	#QDIO mode 
device	0400	osa	osa	--unitadd=0
device	0401	osa	osa	--unitadd=1
device	0402	osa	osa	--unitadd=2
device	0403	osa	osa	--unitadd=3
device	0404	osa	osa	--unitadd=4
device	0405	osa	osa	--unitadd=5
device	0406	osa	osa	--unitadd=6
device	0407	osa	osa	--unitadd=7
device	0408	osa	osa	--unitadd=8
device	0409	osa	osa	--unitadd=9
#device	040A	osa	osa	--unitadd=A
#device	040B	osa	osa	--unitadd=B
#device	040C	osa	osa	--unitadd=C
#...

[manager]
name	awsckd	0003
device	0A89	3390	3390	/volumes/B5USR1
device	0A99	3390	3390	/volumes/B5PAGC
device	0A98	3390	3390	/volumes/B5PRD4
device	0A80	3390	3390	/volumes/B5RES1
device	0A8B	3390	3390	/volumes/B5PRD5
...

利用予定のOSAPORTで使用するはずのアドレスが、devicemap上ではコメントアウトされていた。
恐らく通信用に使用するOSA用のアドレスは10個までという内部的な制約があるのではないかと思われるが、マニュアルに記載は見当たらない。
事前に発見できたので問題は顕在化しなかったが、恐らくこのまますすめるとネットワークの疎通ができない問題が発生していたのではないかと推察される。
これ、かなり危険なトラップだと思われる...

対応措置

WIB管理コンソール上の操作で「イメージの作成」を行う際にIPL情報をカスタマイズすることができる。ここで、デフォルトではソースのz/OS環境で使用されていた通信装置用のアドレスが全て定義されることになる(おそらくIODFに含まれるOSA用のアドレスが全て含まれると思われる)。これが10以上あると後半がコメントアウトされてしまうと思われるため、使用するアドレス(当該TRL Major NodeのREAD,WRITE,DATAPATHに指定しているアドレス)以外は全て削除しておく必要がある。

この部分

Case5: IPL失敗/IEA303W ABEND 878

事象

WIBを使用して作成したカスタム・イメージを元にWazi aaS仮想サーバーを作成し、起動しようとしたところ、IPL時に以下のエラーで失敗。

IEA303W ABEND 878 reason 00000004 during initialization UNDER RIM IEAVNP23

※一度起動できた環境でも、その後IPLし直した時に上の878 ABENDが発生することがあった。そのまま何度か再起動をリトライしているとIPLできる場合がある。このエラーが出る場合と出ない場合の条件の差異が不明(このあたりのメモリの使われ方は内部仕様の部分が多く詳細は公開されていない模様)。SQA/ESQAのエリアがギリギリの状態でメモリの使われ方か何かの要因でたまたまうまくいく場合とうまくいかない場合があると思われる。

調査/確認

過去事例調査。
この辺とか
https://groups.google.com/g/bit.listserv.ibm-main/c/NtK-dviVv-U

NIP処理中にSQA/ESQAのサイズ不足でエラーになっているらしい。
LOADxxにINITSQA の指定を追記してIPL, NIP処理用のSQA/ESQAサイズを増やすことで解決している例が多い。

参考

z/OS - Statements and parameters for LOADxx

INITSQA
The INITSQA statement allows more SQA and ESQA storage to be reserved for IPL and NIP processing when the default amount is not sufficient. Increasing the minimum below the line SQA allocation must be done with caution to ensure that it does not affect the lower boundary of CSA storage. If a syntax error exists, the entire statement is ignored and message IEA368I is issued.

対応措置

LOADxxのINITSQAを指定することで対応

LOADxx設定例

...
INITSQA  0960K 0015M
...

※INITSQAパラメーターを記述する場所が厳密に決まっているので注意！(詳細は上のマニュアル参照のこと)
1番目のパラメーターは10桁目から始まる必要があります。
各パラメーターは4桁の数字+(K or M)で指定する必要があります。
二つのパラメーターの間の1バイトはブランクである必要があります。(ここに","を入れていたりするとエラーとなります。)

設定変更後、WIBによるボリュームの抽出からやり直してリトライ。(何度か試してうまくIPLができてWazi aaSに接続できればそこで修正も可)

Case6: TCP/IP Profile不備

事象

WIBを使用して作成したカスタム・イメージを元にWazi aaS仮想サーバーを作成し、起動しようとしたところ、IPLはできたが、TN3270やFTPなどサブシステムがポートをListenできない状況。

調査/確認

D TCPIP,<TCPIPJobName>,NETSTAT,CONNで確認すると、何もエントリーが表示されない状態。
マスターコンソールに以下のようなエラーが出力されていた。

EZZ6011I TN3270 BPX1SOC FAILED, RC = 00000070 RSN = 74580296

過去事例など確認すると、TLS設定を有効化したときに同様のエラーが生じているケースがあった。今回はTLSは使用しないはず。
TCP/IPのプロファイルを既存環境のものとWazi aaSインスタンスで使われているものを比較すると、TLS関連で不要と思われるパラメータの指定が追加されていた。

TCP/IPプロファイルは、WIB提供ユーティリティー zOS-cloud-prepare というツールで生成したものを使用していた。生成されたプロファイルをよく見てみると、TCPCONFIG TTLSが勝手に追加されていたり、自動起動のサーバーやポート番号などは既存の定義を全然引き継いでくれていなかったりした。
ATTLSの構成やPolicy Agentの起動などが勝手に含まれてしまっているために先のようなエラーが生じていたものと思われる。

参考

zOS-cloud-prepareというツールの位置づけが、マニュアル上かなり微妙な書き方になっている。

Option 1: Using the zOS-cloud-prepare tool to automatically create z/OS configuration

You can automatically create a z/OS configuration (PARMLIB, PROCLIB, TCPPARMS, IPLPARM) by using the IBM-provided zOS-cloud-prepare tool. This tool runs in a running z/OS UNIX System Services environment and creates a new load suffix that contains a templates configuration so that the z/OS can run in a Wazi as a Service environment successfully.

既存の構成をベースに作ってくれるのでそのまま使えそうにも見えるが、よーく見てみるとテンプレート構成を作ってくれる、という書き方になっている。
このツールを信頼しすぎてはいけない。

対応措置

zOS-cloud-prepare Toolで生成された各種プロファイルの見直しを実施。IPアドレスやデフォルト・ルートなどのシンボル化する部分についての情報以外は、きちんと現行構成に合わせて手動でカスタマイズする必要あり。

各種プロファイルを修正後、WIBによるボリュームの抽出からやり直し、リトライ。
結果意図したプロファイルでTCP/IPスタックが稼働し、各サブシステムのポートがListenされ、外部との通信も可能となった。PCOMからTN3270に接続しTSOに入れることも確認できた。
めでたしめでたし。

Case7: z/OS側SSHユーザーの設定不備

事象

別のz/OS環境のVOLを抽出しようとしてWIB管理コンソールから「コンポーネントの作成」を実施しようとするとエラーが発生。

具体的には以下の画面でユーザーID、パスワードを入力してソース環境のz/OSにSSH接続すると...

以下のようなエラーが表示される。

ZD&T 抽出ユーティリティー SFTP モジュールの zDTMainframeSFTP.jar の {0} バージョンの検査が、予期しない理由で失敗しました。
原因: Checking {0} version for the ZD&T extraction utility SFTP module zDTMainframeSFTP.jar failed with unexpected reason.
コード: 70991

このようなエラーが出るものの、OKをクリックすると次のボリューム選択の画面に進む。VOLUMEのリストも表示されるため、SSH接続、Extraction Utilityの実行が行えているように見える。
しかし、その後VOLUMEを選択してVOLUME抽出を行おうとすると失敗する。

調査

WIBサーバーのログを確認すると、以下のようなエラーが出ている。

WIBサーバーのログ

/opt/ibm/wib/wib-server/logs/messages.log

[5/3/24, 7:24:44:027 JST] 00000034 com.ibm.zdt.utility.ZSystemRequestProcessesCommon            I [ZDT-LOG-INFO] zDTMainframeSFTP.jar version is expected to be: 14.1.0
[5/3/24, 7:24:45:486 JST] 00000034 com.ibm.zdt.utility.ZSystemRequestProcessesCommon            W [ZDT-LOG-WARN]  Running 'java -Xshareclasses:name=zdt-sftp -Xshareclasses:groupAccess -Xshareclasses:nonpersistent -Xshareclasses:nonfatal -jar /usr/lpp/IBM/zdt//zDTMainframeSFTP.jar --version' got error output: stdout: zd&t output starts here:
, stderr: <empty>
[5/3/24, 7:24:45:500 JST] 00000034 com.ibm.zdt.rest.v1.services.BaseJPAService                  E [ZDT-LOG-ERROR] checkZosUtilityVersion exception with no message.
com.ibm.zdt.utility.ZdtException,error code:70991
 ZdtResponse: Response code: 70991
com.ibm.zdt.utility.ZdtException,error code:70991
 ZdtResponse: Response code: 70991
        at com.ibm.zdt.utility.ZSystemRequestProcessesCommon.matchSFTPJarVersion(ZSystemRequestProcessesCommon.java:267)
        at com.ibm.zdt.rest.logic.ZSystemRequestProcesses.matchZosUtilityVersion_aroundBody8(ZSystemRequestProcesses.java:238)
        at com.ibm.zdt.rest.logic.ZSystemRequestProcesses$AjcClosure9.run(ZSystemRequestProcesses.java:1)
        at org.aspectj.runtime.reflect.JoinPointImpl.proceed(JoinPointImpl.java:179)
        at com.ibm.zdt.aspectj.AspectJHandler.logEntryExit(AspectJHandler.java:54)
        at com.ibm.zdt.aspectj.LoggingAspectRestAPI.around(LoggingAspectRestAPI.java:41)
        at com.ibm.zdt.rest.logic.ZSystemRequestProcesses.matchZosUtilityVersion(ZSystemRequestProcesses.java:232)
        at com.ibm.zdt.rest.v1.services.ZServices.checkZosUtilityVersion_aroundBody24(ZServices.java:1159)
        at com.ibm.zdt.rest.v1.services.ZServices$AjcClosure25.run(ZServices.java:1)
        at org.aspectj.runtime.reflect.JoinPointImpl.proceed(JoinPointImpl.java:179)
        at com.ibm.zdt.aspectj.AspectJHandler.logEntryExit(AspectJHandler.java:54)
        at com.ibm.zdt.aspectj.LoggingAspectRestAPI.around(LoggingAspectRestAPI.java:41)
        at com.ibm.zdt.rest.v1.services.ZServices.checkZosUtilityVersion(ZServices.java:1120)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:566)
        at com.ibm.ws.jaxrs20.cdi.component.JaxRsFactoryImplicitBeanCDICustomizer.serviceInvoke(JaxRsFactoryImplicitBeanCDICustomizer.java:352)
        at com.ibm.ws.jaxrs20.server.LibertyJaxRsServerFactoryBean.performInvocation(LibertyJaxRsServerFactoryBean.java:642)
        at com.ibm.ws.jaxrs20.server.LibertyJaxRsInvoker.performInvocation(LibertyJaxRsInvoker.java:161)
        at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:101)
        at com.ibm.ws.jaxrs20.server.LibertyJaxRsInvoker.invoke(LibertyJaxRsInvoker.java:276)
        at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:213)
        at com.ibm.ws.jaxrs20.server.LibertyJaxRsInvoker.invoke(LibertyJaxRsInvoker.java:460)
        at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:112)
        at org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:59)
        at org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(ServiceInvokerInterceptor.java:96)
        at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:307)
        at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:127)
        at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:278)
        at com.ibm.ws.jaxrs20.endpoint.AbstractJaxRsWebEndpoint.invoke(AbstractJaxRsWebEndpoint.java:139)
        at com.ibm.websphere.jaxrs.server.IBMRestServlet.handleRequest(IBMRestServlet.java:148)
        at com.ibm.websphere.jaxrs.server.IBMRestServlet.doPost(IBMRestServlet.java:106)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:706)
        at com.ibm.websphere.jaxrs.server.IBMRestServlet.service(IBMRestServlet.java:98)
        at com.ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1260)
        at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:748)
        at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:445)
        at com.ibm.ws.webcontainer.filter.WebAppFilterManager.invokeFilters(WebAppFilterManager.java:1361)
        at com.ibm.ws.webcontainer.filter.WebAppFilterManager.invokeFilters(WebAppFilterManager.java:1077)
        at com.ibm.ws.webcontainer.servlet.CacheServletWrapper.handleRequest(CacheServletWrapper.java:77)
        at com.ibm.ws.webcontainer40.servlet.CacheServletWrapper40.handleRequest(CacheServletWrapper40.java:87)
        at com.ibm.ws.webcontainer.WebContainer.handleRequest(WebContainer.java:969)
        at com.ibm.ws.webcontainer.osgi.DynamicVirtualHost$2.run(DynamicVirtualHost.java:283)
        at com.ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink$TaskWrapper.run(HttpDispatcherLink.java:1248)
        at com.ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink.wrapHandlerAndExecute(HttpDispatcherLink.java:470)
        at com.ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink.ready(HttpDispatcherLink.java:429)
        at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.handleDiscrimination(HttpInboundLink.java:569)
        at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.handleNewRequest(HttpInboundLink.java:503)
        at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.processRequest(HttpInboundLink.java:363)
        at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.ready(HttpInboundLink.java:330)
        at com.ibm.ws.http.channel.h2internal.H2StreamProcessor$Http2Ready.run(H2StreamProcessor.java:1811)
        at com.ibm.ws.threading.internal.ExecutorServiceImpl$RunnableWrapper.run(ExecutorServiceImpl.java:247)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:839)

WIBサーバーで行われている操作をコマンド・レベルで疑似的に実行してみてうまくいくかどうかをチェックしていく。

WIBサーバー → z/OSへのSSH接続
ssh <zOS_SSHUser>@<zOS_HostName> → OK
z/OSのUSSシェルで(1のSSH接続した状態で) javaコマンド実行
java -version → NG (killされた)
z/OSのUSSシェルで(1のSSH接続した状態で) zdtAuth環境変数確認
echo $zdtAuth → OK (.profileに設定された値が表示される)
z/OSのUSSシェルで(1のSSH接続した状態で) sftpサーバーへの接続確認
sftp -P <portNumber> <sftpUser>@<sftpHostName> → OK
※初めての接続時にはAre you sure you want to continue connection (yes/no)?という確認が行われ、yesを返すとknown_hostsへの登録が行われ、2回目以降は聞かれなくなる。

z/OSのSSHユーザーでjavaが実行できない状態であったのが原因。

対応措置

対象のz/OSではJava17とJava8が導入されており、Java17の稼働に問題があったようなので、Java8を使用することで回避(SSHユーザーの.profileのPATH環境変数にてJava8のパスを指定)。

WIBサーバーからSSHでz/OSに接続し、以下のコマンドでバージョン情報が返されればOK
java -jar /usr/lpp/IBM/zdt/zDTMainframeSFTP.jar --version

Case8: LOADxx不備

事象

WIB経由で作成したカスタム・イメージを元にWazi aaS仮想サーバーを作成し、サーバーを開始させると、IBM Cloudコンソール上は開始済みとなるが、z/OSは起動しない。
シリアル・コンソールも以下のエラーで接続できない。

コンソール接続エラー
コンソールが使用中か、まだユーザーがログイン可能になっていません。もう一度実行して、すべてのアクティブなコンソール・セッションを強制的に切断します。

※具体的なエラー情報が何も確認できない！

調査

何度か仮想サーバーの再起動や、ブラウザのキャッシュのクリアなども実施したが、状況は改善されない。
シリアル・コンソール(z/OSのマスター・コンソール)に接続できないので、IPLの初期段階、あるいはIBM Zエミュレーターの起動でエラーになっているものと推察される。
具体的な状況を確認するには、起動に失敗した仮想サーバーにアタッチされているデータ・ボリューム(ブロック・ストレージ)の中身を確認する必要がある。このボリュームをマウントして中身を確認するために別途仮想サーバーを立てる必要がある。
Wazi aaSは zLinuxがベースとなっているが、IA/Linuxからでもこのボリュームの参照は可能。今回WIBサーバーを稼働させるためのIA/Linux(RHEL)をIBM Cloud上の仮想サーバーとして用意していたので、このRHELを使用することにする。ログ取得の手順は以下の通り。

1. Wazi aaS仮想サーバーからデータボリュームを切り離す

IBM CloudコンソールにてWazi aaS仮想サーバーを開き、データ・ボリュームを切り離す

画面イメージ

2. 切り離したデータボリュームをRHELに接続

事前にRHELにsshで接続してブロック・デバイスの状況を確認しておく。

lsblkコマンド例

[root@wibadm01 ~]# lsblk
NAME   MAJ:MIN RM   SIZE RO TYPE MOUNTPOINT
vda    252:0    0   250G  0 disk
tqvda1 252:1    0     1M  0 part
tqvda2 252:2    0   100M  0 part /boot/efi
mqvda3 252:3    0 249.9G  0 part /
vdb    252:16   0   390K  0 disk
vdc    252:32   0    44K  0 disk
vdd    252:48   0   500G  0 disk
mqvdd1 252:49   0   500G  0 part /data

IBM Cloudコンソールにて上で切り離したデータ・ボリュームをRHELサーバーにアタッチする。

画面イメージ

ストレージ・ボリュームの欄の接続をクリック

上で切り離したデータ・ボリュームを選択

データ・ボリュームが追加された状態

3. RHEL上にデータ・ボリュームをマウントして起動失敗時のログを取得

RHELにsshで接続し、ブロック・デバイスの状況を再度確認。

lsblkコマンド例

[root@wibadm01 ~]# lsblk
NAME   MAJ:MIN RM   SIZE RO TYPE MOUNTPOINT
vda    252:0    0   250G  0 disk
tqvda1 252:1    0     1M  0 part
tqvda2 252:2    0   100M  0 part /boot/efi
mqvda3 252:3    0 249.9G  0 part /
vdb    252:16   0   390K  0 disk
vdc    252:32   0    44K  0 disk
vdd    252:48   0   500G  0 disk
mqvdd1 252:49   0   500G  0 part /data
vde    252:64   0    66G  0 disk

最後の行(vde)が追加されたことが確認できる。このデバイスを適当なマウントポイントにマウントする。

マウント例

[root@wibadm01 ~]# mount -t ext4 /dev/vde /mnt

マウントされたファイルシステムのツリー構造を確認

[root@wibadm01 ~]# cd /mnt
[root@wibadm01 /mnt]# tree --charset C .
.
|-- devmap
|-- env-overrides
|-- logs
|   |-- journal
|   |   `-- 7d9c2954605c44958ee376346accd6e1
|   |       `-- system.journal
|   `-- zpdt
|       |-- awsstart_p875_000001.log
|       |-- dv_0240_p907_000001.log
|       |-- dv_0241_p908_000001.log
|       |-- dv_0242_p909_000001.log
|       |-- dv_0700_p918_000001.log
|       |-- dv_5D20_p915_000001.log
|       |-- dv_5D21_p916_000001.log
|       |-- dv_5D22_p911_000001.log
|       |-- dv_5D23_p912_000001.log
|       |-- dv_5D24_p914_000001.log
|       |-- dv_5D2D_p917_000001.log
|       |-- dv_5D2E_p913_000001.log
|       |-- log_console_p875_t2024-05-09_23-20-25.txt
|       `-- tnportl2_p920.log
|-- lost+found
|-- MN25C1
|-- MN25T1
|-- MN25T2
|-- MN25U1
|-- MN25U2
|-- MN25W1
|-- properties.json
`-- ZM5D2E

5 directories, 25 files

これらのファイルのうち、以下のものを取得する。

devmap
env-overrides
logs以下の全てのログファイル
properties.json

logs/zpdt/log_console_xxx.txtファイルの中身を確認。

log_console_xxx.txt

...
INFO: 050924 01:47:55: MIP: AWSMIP008I zArchitecture IPL mode (ZARCH ONLY=ON)
LOG : 050924 01:47:56: CPU: IPL started on CPU 0
LOG : 050924 01:47:56: CPU: IPR started for CPU 0
LOG : 050924 01:47:56: CPU: CPU reset
LOG : 050924 01:47:56: CPU: IPR complete for CPU 0
LOG : 050924 01:47:56: CPU: IPL bootstrap successful for device 9F50
LOG : 050924 01:47:57: CPU: Accepted code 0 cpu-0
LOG : 050924 01:47:57: CPU: Short PSW Change 00080008000668
LOG : 050924 01:47:57: KVM: KVM SET MP STATE: target CPU 0 state-7
INFO: 050924 01:47:57: STA: AWSSTA059I System Initialization complete
INFO: 050924 01:47:57: STA: AWSSTA012I All configured subsystem started
LOG : 050924 01:47:57: KVM: left cpu run loop rc=4
LOG : 050924 01:47:57: KVM: KVM SET MP STATE: target CPU 0 state-5
LOG : 050924 01:47:56: CPU: Disable Wait
INFO: 050924 01:47:57: EMI: AWSEMI307I Warning Disable Wait CPU 0 = 00020000 00000000 00000000 001000B1
...

上に抜粋したメッセージのうち、最後のメッセージからコード"0B1"でz/OSがDISABLE WAIT状態になっていることが確認できた。

AWSEMI307I Warning Disable Wait CPU 0 = 00020000 00000000 00000000 001000B1

末尾の 001000B1 に着目
参考: Wait state codes in z/Architecture mode

この部分のさらに最後の3桁部分 0B1 部分がWait state codeを示す。

参考: Wait state code: 0B1

System initialization cannot continue because of a problem in the LOADxx parmlib member, the I/O definition file (IODF) data set, or a device.
The right-most four bytes of the program status word (PSW) have the following format:
xrr00www
...
The reason code (rr) is one of the following:
01
The required data set was not found.

抽出元のz/OS環境のLOADxxを確認すると、今回Wazi aaS用に用意したLOADxxのIODFの指定が間違っていたことにより、IODFのデータセットが見つからずにDISABLE WAIT状態になっていたことが分かった。

4. RHELからデータボリュームをアンマウントし、切り離す

アンマウント

[root@wibadm01 ~]# umount /mnt

データ・ボリュームをRHELから切り離す。

画面イメージ

対応措置

抽出元z/OS環境にて、Wazo aaS用のLOADxxを正しく修正し、VOLUME抽出をやり直し(WIBコンソールにて、コンポーネントの編集画面から、変更されたVOLUMEのみ抽出)。
その後、イメージのデプロイ、仮想サーバーの作成をリトライ。

教訓

オンプレ環境のz/OSイメージをWIB経由でIBM Cloud上に複製する過程では、多種多様な要素技術が関与しています。各エリアの担当者も多数関わってくる話になります。
まだ成熟していない技術があったり、一方で頻繁にUpdateされていく部分もあったりします。そのような細かい部分の齟齬で一回でうまくいくことは少ないのではないかと思われます。すなわち、何度かTry&Errorを繰り返すことは必要だと考えておいた方がよさそうです。

既存z/OS環境を移植する際には、対象VOLを抽出してそれをWazi aaS用に加工する作業が入りますので、対象のVOLの数/サイズが、移植に要する時間に顕著に影響を及ぼします。
最初の1回目の移植手順を確立できるまでは、まずはできるだけ軽量な範囲に絞ってVOLを選定し、それで移植ができるか確認するのがよいでしょう。(例えば、最低限z/OSが起動して TSO, TCP/IP, TN3270あたりが稼働してPCOM接続確認ができるくらいのイメージ)

例えば、数時間かけて大量のVOLを吸い上げてようやくIBM Cloud上にWazi aaSインスタンスを作ったとして、TCP/IPプロファイルのどこか一か所不備があってネットワークがつながらないとなった場合、IBM Cloud側で修正する術が無いので、オンプレ側で修正して、VOLUMEの抽出、カスタムイメージの作成などをやり直さないといけません。(VOLUME抽出は変更が入ったものだけ抽出すればよいですが、カスタムイメージは1から作り直しです。)

一旦極小環境にて一気通貫でWazi aaSインスタンスが起動して接続できることが確認できてから、各種必要なVOLを含めた移植をする、というのがおすすめです。

参考: 処理時間

参考までに、どのくらいのVOL数/サイズの規模のものを移植した場合にどのくらいの時間がかかったか、だいたいの目安を記載しておきます。
ネットワーク通信速度やマシン性能にも依存しますのであくまで一つの目安程度に..

コンポーネントの作成処理時間 (z/OS => SFTPサーバー)

z/OS上でExtraction UtilityによりVOLごとに圧縮ファイル(.gzファイル)を作成し、SFTPサーバーへ転送を行う処理

SYSRES用ボリューム群

VOL数: 31本
圧縮後サイズ: 113.65GB

並行度=1で抽出した場合の所要時間: 約4時間18分
速度: 約1.35GB/min

※多くが3390-3型、一部9型が含まれる

Data用ボリューム群

VOL数: 132本
圧縮後サイズ: 348.89GB

並行度=4で抽出した場合の所要時間: 約26分
速度: 約4.37GB/min

※多くが3390-3型、一部9型が含まれる

その他 (変更したVOLのみ抽出したケース)

VOL数: 2本(9型)
圧縮前サイズ: 17.8GB
圧縮後サイズ: ?? (8割くらいか？)

並行度=2で抽出した場合の所要時間: 約20分
速度: 約0.63GB/min

デプロイ処理(1) / SFTPサーバー => ICOS

SFTPサーバーからICOSにVOLファイルを転送し、IPLに必要なdevmapファイル等を生成する処理

VOL数: 163本 (SYSRES + Data)
圧縮後サイズ: 462.54

所要時間: 約10分
速度: 約46GB/min

デプロイ処理(2) / ICOS => カスタム・イメージ+スナップショット

吸い上げたVOL情報を、カスタム・イメージ+スナップショット(仮想サーバー作成の元になる形式)にフォーマット変換を行う処理

VOL数: 163本 (SYSRES + Data)
圧縮後サイズ: 462.54

Python処理所要時間: 約30分
速度: 約46GB/min

カスタム・イメージ+スナップショット作成処理所要時間: 約55分
速度: 約8.4GB/min

You get articles that match your needs
You can efficiently read back useful information
You can use dark theme

What you can do with signing up

Wazi aaS: クラウド上でのメインフレーム開発環境構築 - (7)' Wazi Image Builder - Trouble Shootingメモ

はじめに

関連記事

発生事象/対応措置例

Case1: RACF DASDVOLクラス権限

事象

調査/確認

参考

対応措置

Case2: IBM Cloudリソース・アクセス権限

事象

調査/確認

参考

対応措置

Case3: gzファイル破損

事象

調査/確認

対応措置

Case4: 通信装置アドレス数の制約

事象/調査/確認

対応措置

Case5: IPL失敗/IEA303W ABEND 878

事象

調査/確認

参考

対応措置

Case6: TCP/IP Profile不備

事象

調査/確認

参考

対応措置

Case7: z/OS側SSHユーザーの設定不備

事象

調査

対応措置

Case8: LOADxx不備

事象

調査

1. Wazi aaS仮想サーバーからデータボリュームを切り離す

2. 切り離したデータボリュームをRHELに接続

3. RHEL上にデータ・ボリュームをマウントして起動失敗時のログを取得

4. RHELからデータボリュームをアンマウントし、切り離す

対応措置

教訓

参考: 処理時間

コンポーネントの作成処理時間 (z/OS => SFTPサーバー)

SYSRES用ボリューム群

Data用ボリューム群

その他 (変更したVOLのみ抽出したケース)

デプロイ処理(1) / SFTPサーバー => ICOS

デプロイ処理(2) / ICOS => カスタム・イメージ+スナップショット