SageMakerでモデルをデプロイしたら「java.lang.IllegalArgumentException: reasonPhrase contains one of the following prohibited characters: \r\n:」エラーが発生した

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

```python
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`になった。

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

```python
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.`から、エントリポイントのスクリプトに問題があると判断。

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

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

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

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

## おわりに
これで１日溶かした。