事象

SageMakerのノートブックインスタンス上にて、チュートリアルなどにある典型的なコードでモデルをデプロイしようとした。

pytorch = PyTorchModel(
    model_data=model_data,
    role=IAM_ROLE_ARN,
    framework_version='1.4.0',
    py_version='py3',
    entry_point=entry_point,
    sagemaker_session=sagemaker_session
)

predictor = pytorch.deploy(
    initial_instance_count=1,
    instance_type='ml.c5.large',
    accelerator_type=None,
    endpoint_name=endpoint_name,
    wait=False
)

デプロイ自体は成功し、エンドポイントのステータスはInServiceになった。

しかし、クライアントからリクエストを投げるとタイムアウトになってしまう。

runtime = boto3.Session().client(service_name='sagemaker-runtime')
response = runtime.invoke_endpoint(
    EndpointName=endpoint_name, 
    ContentType='image/jpeg',
    Accept = '*/*',
    Body=input_data)

エンドポイントのログをクラウドウォッチで確認したところ、次のようなメッセージが表示された。

2020-08-12T16:06:45.579+09:00
2020-08-12 07:06:44,945 [WARN ] W-9000-model com.amazonaws.ml.mms.wlm.WorkerThread - Backend worker thread exception.

2020-08-12T16:06:45.579+09:00
java.lang.IllegalArgumentException: reasonPhrase contains one of the following prohibited characters: \r\n:

2020-08-12T16:06:45.579+09:00
Please provide a model_fn implementation.

2020-08-12T16:06:45.579+09:00
See documentation for model_fn at https://github.com/aws/sagemaker-python-sdk

2020-08-12T16:06:45.579+09:00
# 011at io.netty.handler.codec.http.HttpResponseStatus.<init>(HttpResponseStatus.java:555)

2020-08-12T16:06:45.579+09:00
# 011at io.netty.handler.codec.http.HttpResponseStatus.<init>(HttpResponseStatus.java:537)

2020-08-12T16:06:45.579+09:00
# 011at io.netty.handler.codec.http.HttpResponseStatus.valueOf(HttpResponseStatus.java:465)

2020-08-12T16:06:45.579+09:00
# 011at com.amazonaws.ml.mms.wlm.Job.response(Job.java:85)

2020-08-12T16:06:45.579+09:00
# 011at com.amazonaws.ml.mms.wlm.BatchAggregator.sendResponse(BatchAggregator.java:85)

2020-08-12T16:06:45.579+09:00
# 011at com.amazonaws.ml.mms.wlm.WorkerThread.run(WorkerThread.java:146)

2020-08-12T16:06:45.579+09:00
# 011at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)

2020-08-12T16:06:45.579+09:00
# 011at java.util.concurrent.FutureTask.run(FutureTask.java:266)

2020-08-12T16:06:45.579+09:00
# 011at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)

2020-08-12T16:06:45.579+09:00
# 011at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)

2020-08-12T16:06:45.579+09:00
# 011at java.lang.Thread.run(Thread.java:748)

2020-08-12T16:06:45.579+09:00
2020-08-12 07:06:44,949 [ERROR] W-9000-model com.amazonaws.ml.mms.wlm.BatchAggregator - Unexpected job: 508fce5c-3785-494e-adea-59ca93493837

2020-08-12T16:06:45.579+09:00
2020-08-12 07:06:44,960 [INFO ] epollEventLoopGroup-4-1 com.amazonaws.ml.mms.wlm.WorkerThread - 9000 Worker disconnected. WORKER_STOPPED

2020-08-12T16:06:45.579+09:00
2020-08-12 07:06:44,963 [INFO ] W-9000-model com.amazonaws.ml.mms.wlm.WorkerThread - Retry worker: 9000 in 1 seconds.

2020-08-12T16:06:46.579+09:00
2020-08-12 07:06:46,039 [INFO ] W-9000-model-stdout com.amazonaws.ml.mms.wlm.WorkerLifeCycle - Listening on port: /home/model-server/tmp/.mms.sock.9000

2020-08-12T16:06:46.580+09:00
2020-08-12 07:06:46,039 [INFO ] W-9000-model-stdout com.amazonaws.ml.mms.wlm.WorkerLifeCycle - [PID]52

2020-08-12T16:06:46.580+09:00
2020-08-12 07:06:46,040 [INFO ] W-9000-model-stdout com.amazonaws.ml.mms.wlm.WorkerLifeCycle - MXNet worker started.

2020-08-12T16:06:46.580+09:00
2020-08-12 07:06:46,040 [INFO ] W-9000-model com.amazonaws.ml.mms.wlm.WorkerThread - Connecting to: /home/model-server/tmp/.mms.sock.9000

2020-08-12T16:06:46.580+09:00
2020-08-12 07:06:46,040 [INFO ] W-9000-model-stdout com.amazonaws.ml.mms.wlm.WorkerLifeCycle - Python runtime: 3.6.10

2020-08-12T16:06:46.580+09:00
2020-08-12 07:06:46,042 [INFO ] W-9000-model-stdout com.amazonaws.ml.mms.wlm.WorkerLifeCycle - Connection accepted: /home/model-server/tmp/.mms.sock.9000.

2020-08-12T16:06:46.580+09:00
2020-08-12 07:06:46,374 [INFO ] pool-1-thread-2 ACCESS_LOG - /10.32.0.2:32840 "GET /ping HTTP/1.1" 200 0

2020-08-12T16:06:46.580+09:00
2020-08-12 07:06:46,421 [INFO ] W-9000-model com.amazonaws.ml.mms.wlm.WorkerThread - Backend response time: 379

2020-08-12T16:06:51.581+09:00
2020-08-12 07:06:51,363 [INFO ] pool-1-thread-2 ACCESS_LOG - /10.32.0.2:32840 "GET /ping HTTP/1.1" 200 0

原因

ログのjava.lang.IllegalArgumentException: reasonPhrase contains one of the following prohibited characters: \r\n:とPlease provide a model_fn implementation.から、エントリポイントのスクリプトに問題があると判断。

モデルがない場合のエラー処理コードにて、改行をしていたが、これがまずかったらしい。

    if not os.path.exists(model_path):
        raise FileNotFoundError("Failed to load model with default model_fn: missing file {}."
                                .format(DEFAULT_MODEL_FILENAME))

対策

改行せずに次のように書いたらエラーが発生しなくなった。

    if not os.path.exists(model_path):
        raise FileNotFoundError("Failed to load model with default model_fn: missing file {}.".format(DEFAULT_MODEL_FILENAME))

おわりに

これで１日溶かした。