Debugging Failed Instance Store-Backed Paravirt/HVM Launch - javax.crypto.IllegalBlockSizeException: last block incomplete in decryption on Walrus

Follow

Eucalyptus Version:  3.4.x

ERROR | javax.crypto.IllegalBlockSizeException: last block incomplete in decryption on Walrus - Debugging Failed Instance Store-Backed Paravirtual/HVM Launch

Problem

Instance Store-Backed Paravirtual/HVM fails to reach running state.  

Criteria

  • The cloud user observes the instance lifecycle going from 'pending' to 'terminated' state.
  • The cloud user have configured euca2ools to use the euca2ools configuration file(s) [1].
  • EMI being used by the cloud user is associated with the following errors in the Node Controller (NC) logs:
    • server responded with HTTP code 417 [2]
    • failed to download component
    • failed to provision dependency
  • Bucket associated with registered EMI only contains an ASCII file (this is the manifest.xml file) on Walrus

Cause

The reason that this happens is due to the fact that the cloud user has registered the EMI to host that is running the Cloud Controller (CLC), and not Walrus.  If the cloud user has created a faulty euca2ools configuration file where the value of 's3-url' is the IP of the Cloud Controller (CLC) and Walrus is not registered with that IP, once the image is registered, Walrus tries to decrypt the image.  Since the all the parts of the image are not uploaded to the Walrus bucket, Walrus fails to decrypt the image upon registration to cache the image. 

Additional Confirmation Triage Steps

In addition to the criteria mentioned above, the cloud administrator should do the following to confirm if this issue matches the behavior observed on the Eucalyptus Cloud.

1.  Confirm that the 's3-url' value is not the IP/Eucalyptus DNS name of the Walrus component

2.  The cloud-output log on the Cloud Controller (CLC) component has a similar error output for the EMI involved:

2014-05-21 20:20:22 INFO | Registering image pk=emi-583B37BA ownerId=arn:aws:euare::944786667073:user/admin
2014-05-21 20:20:22 INFO | Triggering cache population in Walrus for: emi-583B37BA
2014-05-21 20:20:22 ERROR | java.lang.RuntimeException: com.eucalyptus.ws.EucalyptusRemoteFault: Action:ProblemAction Code:CacheImageType Id:RelatesTo Error: FailFail

3.  The cloud-error log on the Cloud Controller (CLC) component has a similar error output for the EMI involved:

Wed May 21 20:20:22 2014 ERROR [AsyncRequest:Eucalyptus.walrus:WalrusConfiguration:arn:euca:bootstrap:walrus:walrus:Lines/.class java.util.concurrent.ThreadPoolExecutor$Worker#452] [com.eucalyptus.util.async.AsyncRequest$2.call(AsyncRequest.java):232] java.lang.RuntimeException: com.eucalyptus.ws.EucalyptusRemoteFault: Action:ProblemAction Code:CacheImageType Id:RelatesTo Error: FailFail

4.  The cloud-debug log on the Walrus component contains a similar log flow regarding the image and EMI involved:

Wed May 21 20:20:22 2014 INFO [WalrusImageManager:Bukkit.15] [com.eucalyptus.objectstorage.WalrusImageManager.logWithContext(WalrusImageManager.java):167] [CorrelationId: af5de4a8-0229-4049-bc4b-09ee2b629647 | Account: 000000000000] Processing CacheImage request for utopic-server-x86_64-hvm/utopic-server-cloudimg-amd64-disk1.raw.manifest.xml
Wed May 21 20:20:22 2014 INFO [WalrusImageManager:Bukkit.15] [com.eucalyptus.objectstorage.WalrusImageManager.logWithContext(WalrusImageManager.java):167] [CorrelationId: af5de4a8-0229-4049-bc4b-09ee2b629647 | Account: 000000000000] Decrypting image with manifest: utopic-server-x86_64-hvm/utopic-server-cloudimg-amd64-disk1.raw.manifest.xml
Wed May 21 20:20:22 2014 INFO [WalrusImageManager:Bukkit.15] [com.eucalyptus.objectstorage.WalrusImageManager.logWithContext(WalrusImageManager.java):167] [CorrelationId: af5de4a8-0229-4049-bc4b-09ee2b629647 | Account: 000000000000] Assembling parts for image utopic-server-x86_64-hvm/utopic-server-cloudimg-amd64-disk1.raw.manifest.xml into file: //var/lib/eucalyptus/bukkits/utopic-server-x86_64-hvm/215582b4-5804-4d58-90be-ca532ccfdffe.crypt.gz
Wed May 21 20:20:22 2014 INFO [WalrusImageManager:Bukkit.15] [com.eucalyptus.objectstorage.WalrusImageManager.logWithContext(WalrusImageManager.java):167] [CorrelationId: af5de4a8-0229-4049-bc4b-09ee2b629647 | Account: 000000000000] Assembly of parts complete for image utopic-server-x86_64-hvm/utopic-server-cloudimg-amd64-disk1.raw.manifest.xml
Wed May 21 20:20:22 2014 INFO [WalrusImageManager:Bukkit.15] [com.eucalyptus.objectstorage.WalrusImageManager.logWithContext(WalrusImageManager.java):167] [CorrelationId: af5de4a8-0229-4049-bc4b-09ee2b629647 | Account: 000000000000] Starting decryption for image utopic-server-x86_64-hvm/utopic-server-cloudimg-amd64-disk1.raw.manifest.xml in file //var/lib/eucalyptus/bukkits/utopic-server-x86_64-hvm/215582b4-5804-4d58-90be-ca532ccfdffe.crypt.gz
Wed May 21 20:20:22 2014 ERROR [WalrusImageManager:Bukkit.15] [com.eucalyptus.objectstorage.WalrusImageManager.decryptImage(WalrusImageManager.java):383] javax.crypto.IllegalBlockSizeException: last block incomplete in decryption

5.  The instance lifecycle that was launched with the EMI has a similar DEBUG log output on the Node Controller:

2014-05-22 06:47:28 DEBUG 000031437 startup_thread | [i-B750412B] spawning startup thread
2014-05-22 06:47:28 DEBUG 000031437 vnetStartNetworkManaged | params: vnetconfig=0x7faa6fa2c010, vlan=992, uuid=UNSET, userName=UNSET, netName=UNSET
2014-05-22 06:47:28 INFO 000031437 ensure_directories_exist | creating path /instances/work/AIDCKX4RYUMQCVMSMCPL2/i-B750412B
2014-05-22 06:47:28 DEBUG 000031437 diskutil_ch | ch(own|mod) '/instances/work/AIDCKX4RYUMQCVMSMCPL2/i-B750412B' *.root 771
2014-05-22 06:47:28 DEBUG 000031437 vbr_alloc_tree | [i-B750412B] found 0 prereqs and 2 partitions in the VBR
2014-05-22 06:47:28 DEBUG 000031437 art_alloc | [i-B750412B] allocated artifact 025|i-B750412B size=-1 vbr=(nil) cache=0 file=0
2014-05-22 06:47:28 DEBUG 000031437 walrus_request_timeout | writing GET output to /tmp/walrus-digest-FRF3ft
2014-05-22 06:47:28 INFO 000031437 walrus_request_timeout | downloading http://10.104.10.11:8773/services/Walrus/utopic-server-x86_64-hvm/utopic-server-cloudimg-amd64-disk1.raw.manifest.xml
2014-05-22 06:47:28 DEBUG 000031437 walrus_request_timeout | wrote 7041 byte(s) in 3 write(s)
2014-05-22 06:47:28 INFO 000031437 walrus_request_timeout | downloaded /tmp/walrus-digest-FRF3ft
2014-05-22 06:47:28 DEBUG 000031437 art_alloc | [i-B750412B] allocated artifact 026|emi-583B37BA-e9206036 size=2361393152 vbr=0x7faa87aa84e0 cache=1 file=0
2014-05-22 06:47:28 DEBUG 000031437 art_alloc | [i-B750412B] allocated artifact 027|emi-583B37BA-e9206036 size=2361393152 vbr=0x7faa87aa84e0 cache=0 file=0
2014-05-22 06:47:28 DEBUG 000031437 art_add_dep | [i-B750412B] added to artifact 027|emi-583B37BA-e9206036 artifact 026|emi-583B37BA-e9206036
2014-05-22 06:47:28 DEBUG 000031437 art_add_dep | [i-B750412B] added to artifact 025|i-B750412B artifact 027|emi-583B37BA-e9206036
2014-05-22 06:47:28 DEBUG 000031437 art_alloc | [i-B750412B] allocated artifact 028|prt-07988none-1d3b3a86 size=8376025088 vbr=0x7faa87aa6fb8 cache=1 file=0
2014-05-22 06:47:28 DEBUG 000031437 art_alloc | [i-B750412B] allocated artifact 029|prt-07988none-1d3b3a86 size=8376025088 vbr=0x7faa87aa6fb8 cache=0 file=0
2014-05-22 06:47:28 DEBUG 000031437 art_add_dep | [i-B750412B] added to artifact 029|prt-07988none-1d3b3a86 artifact 028|prt-07988none-1d3b3a86
2014-05-22 06:47:28 DEBUG 000031437 art_add_dep | [i-B750412B] added to artifact 025|i-B750412B artifact 029|prt-07988none-1d3b3a86
2014-05-22 06:47:28 DEBUG 000031437 art_print_tree | [i-B750412B] artifacts tree: 025|i-B750412B cache=0 file=0 creator=(nil) vbr=(nil)
2014-05-22 06:47:28 DEBUG 000031437 art_print_tree | [i-B750412B] artifacts tree: 027|emi-583B37BA-e9206036 cache=0 file=0 creator=0x7faa7f52c4b0 vbr=0x7faa87aa84e0
2014-05-22 06:47:28 DEBUG 000031437 art_print_tree | [i-B750412B] artifacts tree: 026|emi-583B37BA-e9206036 cache=1 file=0 creator=0x7faa7f52d590 vbr=0x7faa87aa84e0
2014-05-22 06:47:28 DEBUG 000031437 art_print_tree | [i-B750412B] artifacts tree: 029|prt-07988none-1d3b3a86 cache=0 file=0 creator=0x7faa7f52c4b0 vbr=0x7faa87aa6fb8
2014-05-22 06:47:28 DEBUG 000031437 art_print_tree | [i-B750412B] artifacts tree: 028|prt-07988none-1d3b3a86 cache=1 file=0 creator=0x7faa7f52d140 vbr=0x7faa87aa6fb8
2014-05-22 06:47:28 DEBUG 000031437 art_implement_tree | [i-B750412B] implementing artifact 025|i-B750412B
2014-05-22 06:47:28 DEBUG 000031437 art_implement_tree | [i-B750412B] implementing artifact 027|emi-583B37BA-e9206036
2014-05-22 06:47:28 DEBUG 000031437 find_or_create_artifact | [i-B750412B] checking work blobstore for 027|emi-583B37BA-e9206036 (do_create=0 ret=1)
2014-05-22 06:47:28 DEBUG 000031437 art_implement_tree | [i-B750412B] implementing artifact 026|emi-583B37BA-e9206036
2014-05-22 06:47:28 INFO 000031437 ensure_directories_exist | creating path /instances/cache/emi-583B37BA-e9206036
2014-05-22 06:47:28 DEBUG 000031437 diskutil_ch | ch(own|mod) '/instances/cache/emi-583B37BA-e9206036' *.* 771
2014-05-22 06:47:28 DEBUG 000031437 find_or_create_artifact | [i-B750412B] checking work blobstore for 026|emi-583B37BA-e9206036 (do_create=0 ret=2)
2014-05-22 06:47:28 INFO 000031437 ensure_directories_exist | creating path /instances/cache/emi-583B37BA-e9206036
2014-05-22 06:47:28 DEBUG 000031437 diskutil_ch | ch(own|mod) '/instances/cache/emi-583B37BA-e9206036' *.* 771
2014-05-22 06:47:29 DEBUG 000031437 diskutil_loop | attaching file /instances/cache/emi-583B37BA-e9206036/blocks
2014-05-22 06:47:29 DEBUG 000031437 diskutil_loop | to /dev/loop7 at offset 0
2014-05-22 06:47:29 DEBUG 000031437 art_implement_tree | [i-B750412B] created a blob for an artifact 026|emi-583B37BA-e9206036 on try 1
2014-05-22 06:47:29 INFO 000031437 walrus_creator | [i-B750412B] downloading http://10.104.10.11:8773/services/Walrus/utopic-server-x86_64-hvm/utopic-server-cloudimg-amd64-disk1.raw.manifest.xml
2014-05-22 06:47:29 DEBUG 000031437 walrus_request_timeout | writing GET/GetDecryptedImage output
2014-05-22 06:47:29 DEBUG 000031437 walrus_request_timeout | from http://10.104.10.11:8773/services/Walrus/utopic-server-x86_64-hvm/utopic-server-cloudimg-amd64-disk1.raw.manifest.xml
2014-05-22 06:47:29 DEBUG 000031437 walrus_request_timeout | to /instances/cache/emi-583B37BA-e9206036/blocks
2014-05-22 06:47:29 INFO 000031437 walrus_request_timeout | downloading http://10.104.10.11:8773/services/Walrus/utopic-server-x86_64-hvm/utopic-server-cloudimg-amd64-disk1.raw.manifest.xml
2014-05-22 06:47:29 DEBUG 000031437 walrus_request_timeout | wrote 267 byte(s) in 1 write(s)
2014-05-22 06:47:29 ERROR 000031437 walrus_request_timeout | server responded with HTTP code 417 for http://10.104.10.11:8773/services/Walrus/utopic-server-x86_64-hvm/utopic-server-cloudimg-amd64-disk1.raw.manifest.xml
2014-05-22 06:47:29 INFO 000031437 walrus_request_timeout | due to error, removing /instances/cache/emi-583B37BA-e9206036/blocks
2014-05-22 06:47:29 ERROR 000031437 walrus_creator | [i-B750412B] failed to download component http://10.104.10.11:8773/services/Walrus/utopic-server-x86_64-hvm/utopic-server-cloudimg-amd64-disk1.raw.manifest.xml
2014-05-22 06:47:29 ERROR 000031437 art_implement_tree | [i-B750412B] failed to create artifact emi-583B37BA-e9206036 (error=1, may retry) on try 1
2014-05-22 06:47:29 DEBUG 000031437 diskutil_unloop | detaching from loop device /dev/loop7
2014-05-22 06:47:29 DEBUG 000031437 art_implement_tree | [i-B750412B] failed to implement artifact 026|emi-583B37BA-e9206036 on try 1
2014-05-22 06:47:29 ERROR 000031437 art_implement_tree | [i-B750412B] failed to provision dependency emi-583B37BA-e9206036 for artifact emi-583B37BA-e9206036 (error=1) on try 1
2014-05-22 06:47:29 DEBUG 000031437 art_implement_tree | [i-B750412B] failed to implement artifact 027|emi-583B37BA-e9206036 on try 1
2014-05-22 06:47:29 ERROR 000031437 art_implement_tree | [i-B750412B] failed to provision dependency emi-583B37BA-e9206036 for artifact i-B750412B (error=1) on try 1
2014-05-22 06:47:29 DEBUG 000031437 art_implement_tree | [i-B750412B] failed to implement artifact 025|i-B750412B on try 1
2014-05-22 06:47:29 ERROR 000031437 create_instance_backing | [i-B750412B] failed to implement backing for instance
2014-05-22 06:47:29 ERROR 000031437 startup_thread | [i-B750412B] failed to prepare images for instance (error=1)
2014-05-22 06:47:29 DEBUG 000031437 change_state | [i-B750412B] state change for instance: Staging -> Shutoff (Pending)

Resolution

Perform the following steps to resolve this issue:

  1. De-register the faulty EMI
    • euca-deregister emi-583B37BA --region admin@
  2. Delete the content and the bucket of the faulty EMI using euca-delete-bundle, with the --clear option.
    • euca-delete-bundle --bucket utopic-server-cloudimg-hvm --prefix utopic-server-cloudimg-amd64-disk1.raw --clear --region admin@
  3. Update the 's3-url' element with the correct IP for Walrus in the euca2ools configuration file.
    • sed --in-place 's/^s3-url\b.*$/s3-url = http:\/\/<IP of Walrus>:8773\/services\/Walrus/g' .euca/euca2ools.ini
  4. Bundle, upload and register the EMI [3]. (The example below demonstrates how to bundle, upload and register an instance store-backed HVM EMI):
    • euca-bundle-image --image utopic-server-cloudimg-amd64-disk1.raw --arch x86_64 --region admin@
    • euca-upload-bundle --bucket utopic-server-cloudimg-hvm --manifest /var/tmp/bundle-8nh4bo/utopic-server-cloudimg-amd64-disk1.raw.manifest.xml --region admin@
    • euca-register --name utopic-server-hvm utopic-server-cloudimg-hvm/utopic-server-cloudimg-amd64-disk1.raw.manifest.xml --virtualization-type hvm --region admin@
  5. Relaunch the EMI as an instance
    • euca-run-instances --key euca-admin --instance-type m1.medium emi-50783D25 --region admin@

References

[1]   Eucalyptus Euca2ools Guide - Working with Euca2ools Configuration Files
[2]   W3.org - HTTP/1.1 Status Code Definitions
[3]   Eucalyptus 3.4 Image Management Guide - Bundle, Upload, and Register an Image with Eucalyptus

 

 

Have more questions? Submit a request

Comments

Powered by Zendesk