Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Platform Software Failed Due to DAL #190

Closed
RodelFMiguel opened this issue Dec 16, 2017 · 21 comments
Closed

Platform Software Failed Due to DAL #190

RodelFMiguel opened this issue Dec 16, 2017 · 21 comments

Comments

@RodelFMiguel
Copy link

Hi,

I have pulled the latest driver and software, however, I am seeing the following message in the aesmd service:
"[ADMIN]EPID Provisioning failed due to network error"

This causes my call to sgx_ra_get_msg1 to timeout/fail.

Here's the details of the setup:

What could be causing this issue? Thanks!

@dtzimmerman
Copy link

Behind a proxy? Configure /etc/aesmd.conf with your proxy details

@RodelFMiguel
Copy link
Author

RodelFMiguel commented Dec 19, 2017

Hi dtzimmerman,

I think this is not a proxy issue since I also did not configure the proxy on my notebook with SGX and the call to sgx_ra_get_msg1 works in my notebook. I would like to add a message from the AESMD after restarting the service:

Dec 18 11:10:23 rodel aesm_service[2748]: The server sock is 0x558401df0940
Dec 18 11:10:23 rodel aesm_service[2748]: [ADMIN]Platform Services initializing
Dec 18 11:10:23 rodel aesm_service[2748]: [ADMIN]Platform Services initialization failed due to DAL
Dec 18 11:10:23 rodel aesm_service[2748]: [ADMIN]White list update request successful for Version: 2

What could cause DAL error when the aesmd is started/restarted? Could this cause the call to sgx_ra_get_msg1 to timeout?

Thanks!

Kind Regards,
Rodel

@andyzyb
Copy link
Contributor

andyzyb commented Dec 19, 2017

DAL is only needed for SGX platform service. In your case, the failure of EPID provisioning is not related to DAL. You can just ignore this error.

@andyzyb
Copy link
Contributor

andyzyb commented Dec 19, 2017

In most of cases, the network failure is coming from a wrong proxy setting. Can you retry your program? May be the network issue is gone now.

@RodelFMiguel
Copy link
Author

Thanks @andyzyb . I have tried to do it again but with the same result. I am sure our network doesn't require an HTTP proxy since I was able to make the sgx_ra_get_msg1 work from my notebook with SGX. Note that I did not configure the /etc/aesmd.conf file in my notebook. Could there be other reasons for this issue? "[ADMIN]EPID Provisioning failed due to network error"

@andyzyb
Copy link
Contributor

andyzyb commented Dec 20, 2017

So far I cannot think of other failure reason since the error message is clearly saying network error. Can you paste a full log of AESM?

@RodelFMiguel
Copy link
Author

RodelFMiguel commented Dec 20, 2017

Hi @andyzyb,
Here's the log from AESM:
$ sudo service aesmd status
● aesmd.service - Intel(R) Architectural Enclave Service Manager
Loaded: loaded (/lib/systemd/system/aesmd.service; enabled; vendor preset: enabled)
Active: active (running) since Tue 2017-12-19 18:40:18 +08; 21h ago
Process: 1310 ExecStart=/opt/intel/sgxpsw/aesm/aesm_service (code=exited, status=0/SUCCESS)
Process: 1263 ExecStartPre=/bin/chmod 0755 /var/run/aesmd/ (code=exited, status=0/SUCCESS)
Process: 1227 ExecStartPre=/bin/chown -R aesmd:aesmd /var/run/aesmd/ (code=exited, status=0/SUCCESS)
Process: 1217 ExecStartPre=/bin/mkdir -p /var/run/aesmd/ (code=exited, status=0/SUCCESS)
Process: 1198 ExecStartPre=/opt/intel/sgxpsw/aesm/linksgx.sh (code=exited, status=0/SUCCESS)
Main PID: 1318 (aesm_service)
Tasks: 5
Memory: 11.9M
CPU: 219ms
CGroup: /system.slice/aesmd.service
└─1318 /opt/intel/sgxpsw/aesm/aesm_service

Dec 19 18:40:18 elephant aesm_service[1318]: The server sock is 0x5654668c8940
Dec 19 18:40:18 elephant aesm_service[1318]: [ADMIN]Platform Services initializing
Dec 19 18:40:18 elephant aesm_service[1318]: [ADMIN]Platform Services initialization failed due to DAL
Dec 19 18:40:19 elephant aesm_service[1318]: [ADMIN]White list update request successful for Version: 2
Dec 19 18:41:20 elephant aesm_service[1318]: [ADMIN]EPID Provisioning initiated
Dec 19 18:41:54 elephant aesm_service[1318]: [ADMIN]EPID Provisioning failed due to network error
Dec 20 16:05:10 elephant aesm_service[1318]: [ADMIN]EPID Provisioning initiated
Dec 20 16:05:42 elephant aesm_service[1318]: [ADMIN]EPID Provisioning failed due to network error
Dec 20 16:06:10 elephant aesm_service[1318]: SGX EPID provisioning network failure
Dec 20 16:06:51 elephant aesm_service[1318]: [ADMIN]EPID Provisioning initiated

Thanks for investigating this. BTW, I can do an HTTP call to any web server outside of our network using HTTPIE. May I know the URL that the sgx_ra_get_msg1 communicates with (to check direct ping/http call to the service)? Thanks.

@llly
Copy link
Contributor

llly commented Dec 21, 2017

The server for EPID provisioning is http://ps.sgx.trustedservices.intel.com/. You should get 405 error code if accessing it manually.

@RodelFMiguel
Copy link
Author

Hi @llly,

Thanks. From the server that shows the EPID provisioning network failure, I can confirm that I can do an http call to it from command line with the proper 405 error message. So, I still don't see why the error is showing EPID provisioning failed due to network error even if I can communicate with the service properly.

One thought that I have is the server's firmware. Can it cause some network error (at least for the SGX SDK API's) if the firmware is outdated?

Thanks!

@llly
Copy link
Contributor

llly commented Dec 22, 2017

I don't think it's caused by firmware.
Could you build and debug version psw installer by make clean; make DEBUG=1 psw_install_pkg, install it and call sgx_ra_get_msg1 ?
Then there will be a more detailed log /var/opt/aesmd/data/internal_log.txt which helps troubleshooting. You can copy it out using root privilege.

@RodelFMiguel
Copy link
Author

Hi @llly,

Here's the log messages:

[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/aesm_logic.cpp|218|service_start|Fri Dec 22 14:58:19 2017]aesm service is starting
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/aesm_logic.cpp|222|service_start|Fri Dec 22 14:58:19 2017]Fail to read extended epid group id, default extended epid group used
[source/le/LEClass.cpp|312|load_enclave_only|Fri Dec 22 14:58:19 2017]Production signed LE loaded, try loading white list now
[source/le/LEClass.cpp|113|white_list_register|Fri Dec 22 14:58:19 2017]le_init_white_list_wrapper return 0
[source/le/LEClass.cpp|113|white_list_register|Fri Dec 22 14:58:19 2017]le_init_white_list_wrapper return 213
[source/oal/aesm_thread.cpp|131|aesm_create_thread|Fri Dec 22 14:58:19 2017]start to create a thread
[source/oal/aesm_thread.cpp|167|aesm_create_thread|Fri Dec 22 14:58:19 2017]thread 0x56283f0fabb0 created successfully
[source/oal/aesm_thread.cpp|131|aesm_create_thread|Fri Dec 22 14:58:19 2017]start to create a thread
[source/oal/aesm_thread.cpp|84|aesm_thread_proc|Fri Dec 22 14:58:19 2017]start running thread 0x56283f0fabb0...
[source/oal/aesm_thread.cpp|95|aesm_thread_proc|Fri Dec 22 14:58:19 2017]thread parameters of thread 0x56283f0fabb0 copied
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/aesm_logic.cpp|143|thread_to_load_qe|Fri Dec 22 14:58:19 2017]start to load qe
[source/oal/aesm_thread.cpp|167|aesm_create_thread|Fri Dec 22 14:58:19 2017]thread 0x56283f0fb3c0 created successfully
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/aesm_long_lived_thread.cpp|116|find_or_insert_iocache|Fri Dec 22 14:58:19 2017]cache size 0
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/aesm_long_lived_thread.cpp|168|find_or_insert_iocache|Fri Dec 22 14:58:19 2017]successfully add ioc 0x56283f0facb0 (status=1,timeout=0) into thread 0x56283e38b2e0
[source/oal/aesm_thread.cpp|131|aesm_create_thread|Fri Dec 22 14:58:19 2017]start to create a thread
[source/oal/aesm_thread.cpp|84|aesm_thread_proc|Fri Dec 22 14:58:19 2017]start running thread 0x56283f0fb3c0...
[source/oal/aesm_thread.cpp|95|aesm_thread_proc|Fri Dec 22 14:58:19 2017]thread parameters of thread 0x56283f0fb3c0 copied
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/aesm_logic.cpp|200|thread_to_init_pse|Fri Dec 22 14:58:19 2017]start to init_ps
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/aesm_logic.cpp|191|thread_to_load_qe|Fri Dec 22 14:58:19 2017]Fail to read EPID Blob
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/aesm_logic.cpp|193|thread_to_load_qe|Fri Dec 22 14:58:19 2017]QE Thread finished succ
[source/oal/aesm_thread.cpp|97|aesm_thread_proc|Fri Dec 22 14:58:19 2017]returned from user defined thread code for thread 0x56283f0fabb0
[source/oal/aesm_thread.cpp|108|aesm_thread_proc|Fri Dec 22 14:58:19 2017]thread 0x56283f0fabb0 change to status AESM_THREAD_PEDNING
[source/oal/aesm_thread.cpp|167|aesm_create_thread|Fri Dec 22 14:58:19 2017]thread 0x56283f0fb5c0 created successfully
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/aesm_long_lived_thread.cpp|349|set_thread_start|Fri Dec 22 14:58:19 2017]succ create thread 0x56283e38b2e0 for ioc 0x56283f0facb0
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/aesm_long_lived_thread.cpp|372|set_thread_start|Fri Dec 22 14:58:19 2017]long flow thread timeout
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/aesm_long_lived_thread.cpp|309|deref|Fri Dec 22 14:58:19 2017]deref ioc 0x56283f0facb0 (ref_count=2,status=1,timeout=0) of thread 0x56283e38b2e0
[source/pse_op/PSDAService.cpp|108|start_service_internal|Fri Dec 22 14:58:19 2017]start_service_internal
[source/oal/aesm_thread.cpp|84|aesm_thread_proc|Fri Dec 22 14:58:19 2017]start running thread 0x56283f0fb5c0...
[source/oal/aesm_thread.cpp|95|aesm_thread_proc|Fri Dec 22 14:58:19 2017]thread parameters of thread 0x56283f0fb5c0 copied
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/aesm_logic.cpp|252|service_start|Fri Dec 22 14:58:19 2017]aesm service is started
[source/pse_op/jhi_proxy.cpp|55|load|Fri Dec 22 14:58:19 2017]Load JHI library failed: libjhi.so: cannot open shared object file: No such file or directory
[source/pse_op/PSDAService.cpp|125|start_service_internal|Fri Dec 22 14:58:19 2017]JHI_Initialize() failed. The return value is 769
[source/pse_op/PSDAService.cpp|246|start_service_internal|Fri Dec 22 14:58:19 2017]PSDAService::start_service_internal() exit
[source/pse_op/PSDAService.cpp|108|start_service_internal|Fri Dec 22 14:58:19 2017]start_service_internal
[source/pse_op/jhi_proxy.cpp|55|load|Fri Dec 22 14:58:19 2017]Load JHI library failed: libjhi.so: cannot open shared object file: No such file or directory
[source/pse_op/PSDAService.cpp|125|start_service_internal|Fri Dec 22 14:58:19 2017]JHI_Initialize() failed. The return value is 769
[source/pse_op/PSDAService.cpp|246|start_service_internal|Fri Dec 22 14:58:19 2017]PSDAService::start_service_internal() exit
[source/pse_op/PSDAService.cpp|108|start_service_internal|Fri Dec 22 14:58:19 2017]start_service_internal
[source/pse_op/jhi_proxy.cpp|55|load|Fri Dec 22 14:58:19 2017]Load JHI library failed: libjhi.so: cannot open shared object file: No such file or directory
[source/pse_op/PSDAService.cpp|125|start_service_internal|Fri Dec 22 14:58:19 2017]JHI_Initialize() failed. The return value is 769
[source/pse_op/PSDAService.cpp|246|start_service_internal|Fri Dec 22 14:58:19 2017]PSDAService::start_service_internal() exit
[source/pse_op/PSEClass.cpp|78|init_ps|Fri Dec 22 14:58:19 2017]Psda not available
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/aesm_http_msg.cpp|97|http_network_init|Fri Dec 22 14:58:19 2017]http init for url http://whitelist.trustedservices.intel.com/SGX/LCWL/Linux/sgx_white_list_cert.bin
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/aesm_logic.cpp|204|thread_to_init_pse|Fri Dec 22 14:58:19 2017]init_ps return (ae_error_t:AESM_PSDA_NOT_AVAILABLE:57)
[source/oal/aesm_thread.cpp|97|aesm_thread_proc|Fri Dec 22 14:58:19 2017]returned from user defined thread code for thread 0x56283f0fb3c0
[source/oal/aesm_thread.cpp|108|aesm_thread_proc|Fri Dec 22 14:58:19 2017]thread 0x56283f0fb3c0 change to status AESM_THREAD_PEDNING
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/aesm_http_msg.cpp|135|http_network_send_data|Fri Dec 22 14:58:19 2017]send data method=0
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/aesm_http_msg.cpp|226|http_network_send_data|Fri Dec 22 14:58:20 2017]get response size=1272
[source/le/LEClass.cpp|113|white_list_register|Fri Dec 22 14:58:20 2017]le_init_white_list_wrapper return 0
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/aesm_long_lived_thread.cpp|422|set_status_finish|Fri Dec 22 14:58:20 2017]set finish status for ioc 0x56283f0facb0(status=1,timeout=0,ref_count=1) of thread 0x56283e38b2e0
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/aesm_long_lived_thread.cpp|424|set_status_finish|Fri Dec 22 14:58:20 2017]set thread 0x56283e38b2e0 to idle
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/aesm_long_lived_thread.cpp|434|set_status_finish|Fri Dec 22 14:58:20 2017]thread handle release for ioc 0x56283f0facb0 and status to idle of thread 0x56283e38b2e0
[source/oal/aesm_thread.cpp|221|aesm_free_thread|Fri Dec 22 14:58:20 2017]start to free thread 0x56283f0fb5c0
[source/oal/aesm_thread.cpp|251|aesm_free_thread|Fri Dec 22 14:58:20 2017]thread 0x56283f0fb5c0 marked to be free
[source/oal/aesm_thread.cpp|97|aesm_thread_proc|Fri Dec 22 14:58:20 2017]returned from user defined thread code for thread 0x56283f0fb5c0
[source/oal/aesm_thread.cpp|113|aesm_thread_proc|Fri Dec 22 14:58:20 2017]resource of thread 0x56283f0fb5c0 has been dealloced
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/aesm_logic.cpp|1000|get_extended_epid_group_id|Fri Dec 22 14:58:37 2017]AESMLogic::get_extended_epid_group
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/aesm_logic.cpp|785|init_quote|Fri Dec 22 14:58:37 2017]init_quote
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/AEClass.h|108|load_enclave|Fri Dec 22 14:58:37 2017]loading enclave 5
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/aesm_logic.cpp|451|get_launch_token|Fri Dec 22 14:58:37 2017]enter function
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/aesm_logic.cpp|595|get_launch_token|Fri Dec 22 14:58:37 2017]enter function
[source/le/LEClass.cpp|375|get_launch_token|Fri Dec 22 14:58:37 2017]try to load Enclave with mrsigner:C5 4A 62 F2 BE 9E F7 6E FB 1F 39 30 AD 81 EA 7F 60 DE FC 1F 5F 25 E0 9B 7C 06 7A 81 5A E0 C6 CB , attr 14, xfrm 7
[source/le/LEClass.cpp|401|get_launch_token|Fri Dec 22 14:58:37 2017]token request returned with ret = 0, status = 0
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/aesm_logic.cpp|563|set_psvn|Fri Dec 22 14:58:37 2017]get PCE isv_svn=4
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/AEClass.h|136|load_enclave|Fri Dec 22 14:58:37 2017]enclave 5 loaded with id 0X3
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/AEClass.h|146|unload_enclave|Fri Dec 22 14:58:37 2017]unload enclave 0X3
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/AEClass.h|108|load_enclave|Fri Dec 22 14:58:37 2017]loading enclave 1
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/aesm_logic.cpp|451|get_launch_token|Fri Dec 22 14:58:37 2017]enter function
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/aesm_logic.cpp|595|get_launch_token|Fri Dec 22 14:58:37 2017]enter function
[source/le/LEClass.cpp|375|get_launch_token|Fri Dec 22 14:58:37 2017]try to load Enclave with mrsigner:EC 15 B1 07 87 D2 F8 46 67 CE B0 B5 98 FF C4 4A 1F 1C B8 0F 67 0A AE 5D F9 E8 FA 9F 63 76 E1 F8 , attr 4, xfrm 7
[source/le/LEClass.cpp|401|get_launch_token|Fri Dec 22 14:58:37 2017]token request returned with ret = 0, status = 0
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/aesm_logic.cpp|546|set_psvn|Fri Dec 22 14:58:37 2017]get QE or PvE isv_svn=5
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/AEClass.h|136|load_enclave|Fri Dec 22 14:58:37 2017]enclave 1 loaded with id 0X4
[source/qe/qe_logic.cpp|101|init_quote|Fri Dec 22 14:58:37 2017]enter fun
[source/qe/qe_logic.cpp|112|init_quote|Fri Dec 22 14:58:37 2017]start read and verify old epid blob
[source/pve/pve_logic.cpp|290|provision|Fri Dec 22 14:58:37 2017]enter fun
[source/pve/pve_logic.cpp|291|provision|Fri Dec 22 14:58:37 2017]start end point selection
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/aesm_long_lived_thread.cpp|116|find_or_insert_iocache|Fri Dec 22 14:58:37 2017]cache size 0
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/aesm_long_lived_thread.cpp|168|find_or_insert_iocache|Fri Dec 22 14:58:37 2017]successfully add ioc 0x7f9368000a70 (status=1,timeout=0) into thread 0x56283e38b220
[source/oal/aesm_thread.cpp|131|aesm_create_thread|Fri Dec 22 14:58:37 2017]start to create a thread
[source/oal/aesm_thread.cpp|167|aesm_create_thread|Fri Dec 22 14:58:37 2017]thread 0x7f9368014d80 created successfully
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/aesm_long_lived_thread.cpp|349|set_thread_start|Fri Dec 22 14:58:37 2017]succ create thread 0x56283e38b220 for ioc 0x7f9368000a70
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/aesm_long_lived_thread.cpp|376|set_thread_start|Fri Dec 22 14:58:37 2017]timeout:5000,timediff: 4982.154951
[source/oal/aesm_thread.cpp|259|aesm_wait_thread|Fri Dec 22 14:58:37 2017]start to wait thread 0x7f9368014d80 for 4982 ms
[source/oal/aesm_thread.cpp|84|aesm_thread_proc|Fri Dec 22 14:58:37 2017]start running thread 0x7f9368014d80...
[source/oal/aesm_thread.cpp|95|aesm_thread_proc|Fri Dec 22 14:58:37 2017]thread parameters of thread 0x7f9368014d80 copied
[source/pve/pve_logic.cpp|342|epid_provision_thread_func|Fri Dec 22 14:58:37 2017]start end point selection
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/endpoint_select_info.cpp|288|start_protocol|Fri Dec 22 14:58:37 2017]enter fun
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/endpoint_select_info.cpp|142|get_url_info|Fri Dec 22 14:58:37 2017]server url blob file not available in persistent storage
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/AEClass.h|146|unload_enclave|Fri Dec 22 14:58:37 2017]unload enclave 0X4
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/AEClass.h|108|load_enclave|Fri Dec 22 14:58:37 2017]loading enclave 2
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/aesm_logic.cpp|451|get_launch_token|Fri Dec 22 14:58:37 2017]enter function
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/aesm_logic.cpp|595|get_launch_token|Fri Dec 22 14:58:37 2017]enter function
[source/le/LEClass.cpp|375|get_launch_token|Fri Dec 22 14:58:37 2017]try to load Enclave with mrsigner:EC 15 B1 07 87 D2 F8 46 67 CE B0 B5 98 FF C4 4A 1F 1C B8 0F 67 0A AE 5D F9 E8 FA 9F 63 76 E1 F8 , attr 14, xfrm 7
[source/le/LEClass.cpp|401|get_launch_token|Fri Dec 22 14:58:37 2017]token request returned with ret = 0, status = 0
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/AEClass.h|136|load_enclave|Fri Dec 22 14:58:37 2017]enclave 2 loaded with id 0X5
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/endpoint_select_info.cpp|317|start_protocol|Fri Dec 22 14:58:37 2017]use parition 8 from PvE
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/endpoint_select_info.cpp|319|start_protocol|Fri Dec 22 14:58:37 2017]Connect to server url "http://ps.sgx.trustedservices.intel.com/" for endpoint selection
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/type_length_value.cpp|491|add_es_selector|Fri Dec 22 14:58:37 2017]create TLV: type (TLV:TLV_ES_SELECTOR:17), size 2, version 1, payload 00 08
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/endpoint_select_info.cpp|336|start_protocol|Fri Dec 22 14:58:37 2017]ES msg1 generated
[source/network/network_encoding_wrapper.cpp|136|aesm_send_recv_msg_encoding|Fri Dec 22 14:58:37 2017]send msg to url http://ps.sgx.trustedservices.intel.com/
[source/network/network_encoding_wrapper.cpp|66|aesm_send_recv_msg_encoding_internal|Fri Dec 22 14:58:37 2017]send msg "02 02 AD 3C 54 34 5A 1A 87 F0 00 00 00 00 06 11 01 00 02 00 08" to server:http://ps.sgx.trustedservices.intel.com/
[source/network/network_encoding_wrapper.cpp|74|aesm_send_recv_msg_encoding_internal|Fri Dec 22 14:58:37 2017]encoded msg 0202AD3C54345A1A87F00000000006EQEAAgAI
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/aesm_http_msg.cpp|97|http_network_init|Fri Dec 22 14:58:37 2017]http init for url http://ps.sgx.trustedservices.intel.com/
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/aesm_http_msg.cpp|135|http_network_send_data|Fri Dec 22 14:58:37 2017]send data method=1
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/aesm_http_msg.cpp|226|http_network_send_data|Fri Dec 22 14:58:39 2017]get response size=1282
[source/network/network_encoding_wrapper.cpp|86|aesm_send_recv_msg_encoding_internal|Fri Dec 22 14:58:39 2017]response msg 0202AD3C54345A1A87F00100000000000003A5EgEALAAAaHR0cDovL3BzLnNneC50cnVzdGVkc2VydmljZXMuaW50ZWwuY29tOjgwFgEBgQRPQK9w8nSWDCKBgD9mn+M6z6jCkjKWx1ymmBup8N2tJDSH3D1KkDsR4VdTVkcPVLPU4mnKxGntnRzfA5QCf5JVpHnW9COaO4u4FEaSV/jqcYrj6s+YGUrOc3YWGFqaIponR4hfzsqMIid/Nr5ZT5i03IGolIcVN6DCjrp2NJrFTC9gsQqf1ypKA5OmZJKZfXl6BWilhey8Ko6VWr6GtMTPeCHccZvXKz5zlDRRybjAnaj5YGyPTgpLGFpqB+S7ESmSrZ9pznj/ZcbQ1JDCG2lbJYjA3OTfzqlTVP6bOnrpM9l+ZpdepxQurUgUk2udOpE6Eo6z2lE3jy4mtMBeE+FXOGiii/HpMW9/KD4TvGu9eWQpA6OytZ5j6wEjlyaNd7sjNekt2qRUGcSUjKHJsTu5BjtiQkdWga/NGTAerzlSq9FC4MCD63FScjVOOzAQjrLvYBl2f2wbs1SgKEk3K4WhfJdSAI/zGeX/hWt2jFiguYlkEQYbY+tsQtgmFK1mb2oXAgHspEll/ekZOwoDpasH7rwINB2Er3161GRljzAf5Ixht4Ue3VqdWnVUN9Vxs1OMUHXimX2weY0sqguy5DYdqzsjdSEnjD+uHJUPbk1bPbWhezQeQC5gpYRL4Q9FZk8ppkpDYXh4YEFND+IV2b6wEINSW2C6XhyNErLhZ6KBBxPT5TPjX7wJb43/lJneAVShzU6JS9fr+YB8XbBtNSLyR4DiujaQYruVueSJU/rE+tw74P4PMz0KcBq8J9qJYhzhqS+au+0IpOea5hEgwRWHHyGjX7cHNoZ7+QLeRCoEa5Z+B6p4vH6ebvk6JRLe/RiXc5X8IH+ngpnz+/ig6XP8gG+kqWFRtIexgcurvywr44lQImVdn/ISwwmhzu2P0wo5IVogQWrZMgFO6xiipnX+gWWuTbwfQ0SZ8hv2zozVtItYCoRmha3qGw3OirFLHRVad4DlSCb6/qZ/sdJ3Gwc5VVFSOB/YR/yIAKACCexBu3FRaDI27/9Sf9gXw1xVAtnyjavBAAEAAQAAAAAAAAAAAAAAAAAAAAAAAAAAbk1eNKVXwBVSex6aWTS7bfkMOj3Kj2Y78yHMX7MqExBuKIQx+/F9kVhsog2V7efs6M31baAIbbIrF4jOoCDoGTSVbqhl+WkgUDram5GsIIu+kZ2s
[source/network/network_encoding_wrapper.cpp|94|aesm_send_recv_msg_encoding_internal|Fri Dec 22 14:58:39 2017]Succ recv msg:0202AD3C54345A1A87F00100000000000003A5EgEALAAAaHR0cDovL3BzLnNneC50cnVzdGVkc2VydmljZXMuaW50ZWwuY29tOjgwFgEBgQRPQK9w8nSWDCKBgD9mn+M6z6jCkjKWx1ymmBup8N2tJDSH3D1KkDsR4VdTVkcPVLPU4mnKxGntnRzfA5QCf5JVpHnW9COaO4u4FEaSV/jqcYrj6s+YGUrOc3YWGFqaIponR4hfzsqMIid/Nr5ZT5i03IGolIcVN6DCjrp2NJrFTC9gsQqf1ypKA5OmZJKZfXl6BWilhey8Ko6VWr6GtMTPeCHccZvXKz5zlDRRybjAnaj5YGyPTgpLGFpqB+S7ESmSrZ9pznj/ZcbQ1JDCG2lbJYjA3OTfzqlTVP6bOnrpM9l+ZpdepxQurUgUk2udOpE6Eo6z2lE3jy4mtMBeE+FXOGiii/HpMW9/KD4TvGu9eWQpA6OytZ5j6wEjlyaNd7sjNekt2qRUGcSUjKHJsTu5BjtiQkdWga/NGTAerzlSq9FC4MCD63FScjVOOzAQjrLvYBl2f2wbs1SgKEk3K4WhfJdSAI/zGeX/hWt2jFiguYlkEQYbY+tsQtgmFK1mb2oXAgHspEll/ekZOwoDpasH7rwINB2Er3161GRljzAf5Ixht4Ue3VqdWnVUN9Vxs1OMUHXimX2weY0sqguy5DYdqzsjdSEnjD+uHJUPbk1bPbWhezQeQC5gpYRL4Q9FZk8ppkpDYXh4YEFND+IV2b6wEINSW2C6XhyNErLhZ6KBBxPT5TPjX7wJb43/lJneAVShzU6JS9fr+YB8XbBtNSLyR4DiujaQYruVueSJU/rE+tw74P4PMz0KcBq8J9qJYhzhqS+au+0IpOea5hEgwRWHHyGjX7cHNoZ7+QLeRCoEa5Z+B6p4vH6ebvk6JRLe/RiXc5X8IH+ngpnz+/ig6XP8gG+kqWFRtIexgcurvywr44lQImVdn/ISwwmhzu2P0wo5IVogQWrZMgFO6xiipnX+gWWuTbwfQ0SZ8hv2zozVtItYCoRmha3qGw3OirFLHRVad4DlSCb6/qZ/sdJ3Gwc5VVFSOB/YR/yIAKACCexBu3FRaDI27/9Sf9gXw1xVAtnyjavBAAEAAQAAAAAAAAAAAAAAAAAAAAAAAAAAbk1eNKVXwBVSex6aWTS7bfkMOj3Kj2Y78yHMX7MqExBuKIQx+/F9kVhsog2V7efs6M31baAIbbIrF4jOoCDoGTSVbqhl+WkgUDram5GsIIu+kZ2s
[source/network/network_encoding_wrapper.cpp|110|aesm_send_recv_msg_encoding_internal|Fri Dec 22 14:58:39 2017]succ decode msg "02 02 AD 3C 54 34 5A 1A 87 F0 01 00 00 00 00 00 00 03 A5 12 01 00 2C 00 00 68 74 74 70 3A 2F 2F 70 73 2E 73 67 78 2E 74 72 75 ...A2 0D 95 ED E7 EC E8 CD F5 6D A0 08 6D B2 2B 17 88 CE A0 20 E8 19 34 95 6E A8 65 F9 69 20 50 3A DA 9B 91 AC 20 8B BE 91 9D AC"
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/endpoint_select_info.cpp|351|start_protocol|Fri Dec 22 14:58:39 2017]start to process ES msg2
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/type_length_value.cpp|242|init_from_tlv_msg|Fri Dec 22 14:58:39 2017]Decode One TLV: type (TLV:TLV_ES_INFORMATION:18), size 44, version 1, payload:00 00 68 74 74 70 3A 2F 2F 70 73 2E 73 67 78 2E 74 72 75 73 74 65 64 73 65 72 76 69 63 65 73 2E 69 6E 74 65 6C 2E 63 6F 6D 3A 38 30
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/type_length_value.cpp|242|init_from_tlv_msg|Fri Dec 22 14:58:39 2017]Decode One TLV: type (TLV:TLV_SIGNATURE:22), size 385, version 1, payload:04 4F 40 AF 70 F2 74 96 0C 22 81 80 3F 66 9F E3 3A CF A8 C2 92 32 96 C7 5C A6 98 1B A9 F0 DD AD 24 34 87 DC 3D 4A 90 3B 11 E1 ...1B B3 54 A0 28 49 37 2B 85 A1 7C 97 52 00 8F F3 19 E5 FF 85 6B 76 8C 58 A0 B9 89 64 11 06 1B 63 EB 6C 42 D8 26 14 AD 66 6F 6A
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/type_length_value.cpp|242|init_from_tlv_msg|Fri Dec 22 14:58:39 2017]Decode One TLV: type (TLV:TLV_PEK:23), size 492, version 2, payload:A4 49 65 FD E9 19 3B 0A 03 A5 AB 07 EE BC 08 34 1D 84 AF 7D 7A D4 64 65 8F 30 1F E4 8C 61 B7 85 1E DD 5A 9D 5A 75 54 37 D5 71 ...A2 0D 95 ED E7 EC E8 CD F5 6D A0 08 6D B2 2B 17 88 CE A0 20 E8 19 34 95 6E A8 65 F9 69 20 50 3A DA 9B 91 AC 20 8B BE 91 9D AC
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/endpoint_select_info.cpp|358|start_protocol|Fri Dec 22 14:58:39 2017]ES Msg2 decoded successfully, ttl 0s
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/endpoint_select_info.cpp|218|verify_signature|Fri Dec 22 14:58:39 2017]PEK signature verified successfully
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/endpoint_select_info.cpp|257|verify_signature|Fri Dec 22 14:58:39 2017]rsa signature verification passed
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/endpoint_select_info.cpp|364|start_protocol|Fri Dec 22 14:58:39 2017]Signature in ES Msg2 verified
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/endpoint_select_info.cpp|368|start_protocol|Fri Dec 22 14:58:39 2017]end point selection succ, provisioning url: http://ps.sgx.trustedservices.intel.com:80
[source/pve/pve_logic.cpp|354|epid_provision_thread_func|Fri Dec 22 14:58:39 2017]estimate msg1 size :859
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/AEClass.h|146|unload_enclave|Fri Dec 22 14:58:39 2017]unload enclave 0X5
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/AEClass.h|108|load_enclave|Fri Dec 22 14:58:39 2017]loading enclave 5
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/AEClass.h|136|load_enclave|Fri Dec 22 14:58:39 2017]enclave 5 loaded with id 0X6
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/AEClass.h|146|unload_enclave|Fri Dec 22 14:58:39 2017]unload enclave 0X6
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/AEClass.h|108|load_enclave|Fri Dec 22 14:58:39 2017]loading enclave 2
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/AEClass.h|136|load_enclave|Fri Dec 22 14:58:39 2017]enclave 2 loaded with id 0X7
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/AEClass.h|146|unload_enclave|Fri Dec 22 14:58:39 2017]unload enclave 0X7
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/AEClass.h|108|load_enclave|Fri Dec 22 14:58:39 2017]loading enclave 5
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/AEClass.h|136|load_enclave|Fri Dec 22 14:58:39 2017]enclave 5 loaded with id 0X8
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/AEClass.h|146|unload_enclave|Fri Dec 22 14:58:39 2017]unload enclave 0X8
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/type_length_value.cpp|396|add_block_cipher_info|Fri Dec 22 14:58:39 2017]create TLV: type (TLV:TLV_BLOCK_CIPHER_INFO:2), size 16, version 1, payload 85 55 2D 9F AF 35 88 8C 0C F7 ED 66 5D CB 55 B7
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/type_length_value.cpp|496|add_psid|Fri Dec 22 14:58:39 2017]create TLV: type (TLV:TLV_PS_ID:9), size 32, version 1, payload DB 1D 19 0A F8 65 BC 2A 69 F5 2A D2 F7 20 22 D7 F8 11 47 85 19 18 AE 24 DE A7 A7 35 CD A0 4F 55
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/type_length_value.cpp|331|add_cipher_text|Fri Dec 22 14:58:39 2017]create TLV: type (TLV:TLV_CIPHER_TEXT:0), size 385, version 1, payload 03 34 4A CC 98 F6 2A 44 70 F9 7E D8 F4 EB 86 30 B5 1C DD F6 2D CA 1D 00 B3 30 32 AE FD 1E 04 23 24 06 E7 57 70 69 01 52 49 20 ...C1 6C 85 EC F2 3E 0E 98 8A 72 96 8A B3 44 64 02 EF 21 C8 17 BA CE 20 BB 14 CE 90 CC 32 FF 67 B3 B7 52 69 84 81 32 82 AC 7D D8
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/type_length_value.cpp|331|add_cipher_text|Fri Dec 22 14:58:39 2017]create TLV: type (TLV:TLV_CIPHER_TEXT:0), size 385, version 1, payload 03 6A D5 39 37 82 6C A6 AD 3F 82 EA 34 5A 16 67 D2 8C 3B 68 11 D2 B2 03 E6 BB C4 9A 6D C6 24 B7 A5 AB 15 E0 64 48 B2 61 45 43 ...02 9C BA CD F8 92 5F C8 09 72 22 8B 80 75 8E 02 C1 2C B2 ED 05 71 C6 92 0F 5F 7A 8A 67 CA 85 E9 47 3F 03 4B A4 29 6F CD F2 54
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/type_length_value.cpp|501|add_platform_info|Fri Dec 22 14:58:39 2017]create TLV: type (TLV:TLV_PLATFORM_INFO:24), size 26, version 1, payload 02 02 02 04 FF 02 00 00 00 00 00 00 00 00 00 00 05 00 04 00 00 00 00 00 00 00
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/type_length_value.cpp|367|add_block_cipher_text|Fri Dec 22 14:58:39 2017]create TLV: type (TLV:TLV_BLOCK_CIPHER_TEXT:1), size 431, version 1, payload FB FD 52 8B 56 93 39 47 BB B1 47 F6 71 40 3B 32 34 41 FB D9 D7 EC 1A DC 00 80 DE E5 1E DB 99 B6 47 77 09 6E 4F EE CE 1C 3A 17 ...DF D1 B2 C9 E9 AE FC F1 C6 C9 1B 5E D9 3F C1 C3 DC 0B 32 6E AA 80 8A 93 20 12 AE D2 F9 E5 57 EA 85 49 01 1A A4 C3 3B 2C 9A 01
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/type_length_value.cpp|430|add_mac|Fri Dec 22 14:58:39 2017]create TLV: type (TLV:TLV_MESSAGE_AUTHENTICATION_CODE:3), size 16, version 1, payload 87 16 E4 DF 26 7C BF DB 7F 3B 24 30 08 02 5B 64
[source/pve/pve_logic.cpp|381|epid_provision_thread_func|Fri Dec 22 14:58:39 2017]msg1 generated with size 859
[source/pve/pve_logic.cpp|387|epid_provision_thread_func|Fri Dec 22 14:58:39 2017]start to send prov msg1 and recv response
[source/network/network_encoding_wrapper.cpp|136|aesm_send_recv_msg_encoding|Fri Dec 22 14:58:39 2017]send msg to url http://ps.sgx.trustedservices.intel.com:80
[source/network/network_encoding_wrapper.cpp|66|aesm_send_recv_msg_encoding_internal|Fri Dec 22 14:58:39 2017]send msg "00 02 DE BD 24 C1 29 6C D1 7A 00 00 00 03 4C 00 01 01 81 03 34 4A CC 98 F6 2A 44 70 F9 7E D8 F4 EB 86 30 B5 1C DD F6 2D CA 1D ...AA 80 8A 93 20 12 AE D2 F9 E5 57 EA 85 49 01 1A A4 C3 3B 2C 9A 01 03 01 00 10 87 16 E4 DF 26 7C BF DB 7F 3B 24 30 08 02 5B 64" to server:http://ps.sgx.trustedservices.intel.com:80
[source/network/network_encoding_wrapper.cpp|74|aesm_send_recv_msg_encoding_internal|Fri Dec 22 14:58:39 2017]encoded msg 0002DEBD24C1296CD17A000000034CAAEBgQM0SsyY9ipEcPl+2PTrhjC1HN32LcodALMwMq79HgQjJAbnV3BpAVJJIHpAx2ovYyOVHsTW8efmQcpL1xs7BS3/g+1vk3M2rt/6dmcdE7HM8EK5l349La+h2RqZoW17RXurdOxCAE8llaJpRen5h4h3Nwm3aqzjB9WWpC5LCr0VnvtAsrod0gkpSjAE60xqUwlaodObFoMo9d9zHsmIPZnxq0nm9cBEmyEvHBZQVIuioeak7nmwC7PCZSbwkOTYEnx9fwUA+a64in74a4ZEQDkV3opkT55xGQM5Eb7YdJZQzeaRm3ayeSZoerGKBSdnVwgc6Y5X/giCDczo91n4DimfVWh/23oEvyDe4E2Pg/hXiZiT/BLWkcOLGbI4SLY5x56Zjye1fMPja3FFAxth4hoHsIREaGPFMQySTz+S4//bj0LexVvghjZhfytfW3euQF4TXsjiuZPBbIXs8j4OmIpyloqzRGQC7yHIF7rOILsUzpDMMv9ns7dSaYSBMoKsfdgBAQGv+/1Si1aTOUe7sUf2cUA7MjRB+9nX7BrcAIDe5R7bmbZHdwluT+7OHDoXw+BFqqFxfNL7KhxOjRih287pZFbUsmpMf4PqqyPuWgLDruwimyaK7rm9rZoQj+po0nKQXgoHGs/ysRY28zLaNN6ylOpqThL4ggCNsllaMmiybEV48L6B4YfDc38k5IZ7UCry+ECLbtUDWw69Lq4e+Ep8xQImrILiPXIN9GMGA2+fGotTA+3rXC2u/g2LQ/coiGUZxxkb0ykTq0AbsWj2s0fXGpzRheR//eXZWlY1CeVtGq+rjVgvSfc+/fVY2gk7AL45Vt0tMuXYIhdK5aF7r4Wl96SQTgCqps5uvH1UjNayklwXMym49W8jDRTKSRiA8zI1jmtpwMUlijSAxiav+iVQrDndWOEb7DidiGBJgQqKT5cgj3p1Mh/AdCjZ0wmfL+jg51GtESOrC8z5Se1zjLg3GzP8S9tduTwY4eDWSO+Nl6ccUyQNPYMq1el3gMw8ufqSpZskPG9hOcff0bLJ6a788cbJG17ZP8HD3AsybqqAipMgEq7S+eVX6oVJARqkwzssmgEDAQAQhxbk3yZ8v9t/OyQwCAJbZA==
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/aesm_http_msg.cpp|97|http_network_init|Fri Dec 22 14:58:39 2017]http init for url http://ps.sgx.trustedservices.intel.com:80
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/aesm_http_msg.cpp|135|http_network_send_data|Fri Dec 22 14:58:39 2017]send data method=1
[source/oal/aesm_thread.cpp|290|aesm_wait_thread|Fri Dec 22 14:58:42 2017]thread 0x7f9368014d80 waiting timeout
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/aesm_long_lived_thread.cpp|380|set_thread_start|Fri Dec 22 14:58:42 2017]wait for ioc 0x7f9368000a70 (status=1,timeout=0,ref_count=2) result:12
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/aesm_long_lived_thread.cpp|309|deref|Fri Dec 22 14:58:42 2017]deref ioc 0x7f9368000a70 (ref_count=2,status=1,timeout=0) of thread 0x56283e38b220
[source/qe/qe_logic.cpp|79|try_reprovision_if_not|Fri Dec 22 14:58:42 2017]pve provision failed:(aesm_error_t:AESM_BUSY:18)
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/aesm_logic.cpp|785|init_quote|Fri Dec 22 14:58:45 2017]init_quote
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/aesm_logic.cpp|785|init_quote|Fri Dec 22 14:58:48 2017]init_quote
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/aesm_logic.cpp|785|init_quote|Fri Dec 22 14:58:51 2017]init_quote
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/aesm_logic.cpp|785|init_quote|Fri Dec 22 14:58:54 2017]init_quote
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/application/aesm_logic.cpp|785|init_quote|Fri Dec 22 14:58:57 2017]init_quote
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/aesm_http_msg.cpp|208|http_network_send_data|Fri Dec 22 14:59:11 2017]fail in connect:52
[source/network/network_encoding_wrapper.cpp|78|aesm_send_recv_msg_encoding_internal|Fri Dec 22 14:59:11 2017]fail to send encoded msg (size=1158) to url:http://ps.sgx.trustedservices.intel.com:80
[source/pve/pve_logic.cpp|391|epid_provision_thread_func|Fri Dec 22 14:59:11 2017]send msg1 via network fail:(ae_error_t:OAL_NETWORK_UNAVAILABLE_ERROR:7)
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/aesm_long_lived_thread.cpp|422|set_status_finish|Fri Dec 22 14:59:11 2017]set finish status for ioc 0x7f9368000a70(status=1,timeout=0,ref_count=1) of thread 0x56283e38b220
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/aesm_long_lived_thread.cpp|424|set_status_finish|Fri Dec 22 14:59:11 2017]set thread 0x56283e38b220 to idle
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/aesm_long_lived_thread.cpp|434|set_status_finish|Fri Dec 22 14:59:11 2017]thread handle release for ioc 0x7f9368000a70 and status to idle of thread 0x56283e38b220
[source/oal/aesm_thread.cpp|221|aesm_free_thread|Fri Dec 22 14:59:11 2017]start to free thread 0x7f9368014d80
[source/oal/aesm_thread.cpp|251|aesm_free_thread|Fri Dec 22 14:59:11 2017]thread 0x7f9368014d80 marked to be free
[source/oal/aesm_thread.cpp|97|aesm_thread_proc|Fri Dec 22 14:59:11 2017]returned from user defined thread code for thread 0x7f9368014d80
[source/oal/aesm_thread.cpp|113|aesm_thread_proc|Fri Dec 22 14:59:11 2017]resource of thread 0x7f9368014d80 has been dealloced

@fqiu1
Copy link
Contributor

fqiu1 commented Dec 22, 2017

@RodelFMiguel, according following line in the log

[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/aesm_http_msg.cpp|208|http_network_send_data|Fri Dec 22 14:59:11 2017]fail in connect:52
[source/network/network_encoding_wrapper.cpp|78|aesm_send_recv_msg_encoding_internal|Fri Dec 22 14:59:11 2017]fail to send encoded msg (size=1158) to url:http://ps.sgx.trustedservices.intel.com:80

It should be a network issue. Can you double check the availability of http://ps.sgx.trustedservices.intel.com:80 on your PC?

@RodelFMiguel
Copy link
Author

@fqiu1 , I have tried the following in the server that doesn't work using HTTPIE command line application in my Ubuntu Server machine:

http http://ps.sgx.trustedservices.intel.com:80

HTTP/1.1 405 Method Not Allowed
Allow: POST
Connection: keep-alive
Content-Length: 0
Date: Fri, 22 Dec 2017 07:42:25 GMT
Request-ID: 170665ac34ac4fd28b0c845b7e1b184e

Furthermore, I did a test using CURL on the same machine:

curl -v http://ps.sgx.trustedservices.intel.com:80

GET / HTTP/1.1
Host: ps.sgx.trustedservices.intel.com
User-Agent: curl/7.47.0
Accept: /

< HTTP/1.1 405 Method Not Allowed
< Date: Fri, 22 Dec 2017 07:50:32 GMT
< Content-Length: 0
< Connection: keep-alive
< Allow: POST
< Request-ID: 22ad26a60f88490d8d26eba7417c01d1
<

  • Connection #0 to host ps.sgx.trustedservices.intel.com left intact

From the logs, there seems to be a point where we can actually communicate with the server:
[source/network/network_encoding_wrapper.cpp|136|aesm_send_recv_msg_encoding|Fri Dec 22 14:58:37 2017]send msg to url http://ps.sgx.trustedservices.intel.com/
[source/network/network_encoding_wrapper.cpp|66|aesm_send_recv_msg_encoding_internal|Fri Dec 22 14:58:37 2017]send msg "02 02 AD 3C 54 34 5A 1A 87 F0 00 00 00 00 06 11 01 00 02 00 08" to server:http://ps.sgx.trustedservices.intel.com/
[source/network/network_encoding_wrapper.cpp|74|aesm_send_recv_msg_encoding_internal|Fri Dec 22 14:58:37 2017]encoded msg 0202AD3C54345A1A87F00000000006EQEAAgAI
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/aesm_http_msg.cpp|97|http_network_init|Fri Dec 22 14:58:37 2017]http init for url http://ps.sgx.trustedservices.intel.com/
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/aesm_http_msg.cpp|135|http_network_send_data|Fri Dec 22 14:58:37 2017]send data method=1
[/home/rodel/Projects/linux-sgx/psw/ae/aesm_service/source/aesm/extension/aesm_http_msg.cpp|226|http_network_send_data|Fri Dec 22 14:58:39 2017]get response size=1282
[source/network/network_encoding_wrapper.cpp|86|aesm_send_recv_msg_encoding_internal|Fri Dec 22 14:58:39 2017]response msg

Thanks!

Kind Regards,
Rodel

@fqiu1
Copy link
Contributor

fqiu1 commented Dec 28, 2017

@RodelFMiguel your analysis is reasonable, but I cannot reproduce your problem locally. The error code returned from curl is 52(CURLE_GOT_NOTHING), in my understanding, the server will not just drop your request even if you have something wrong in the request. Would you please use some http debug tool(i.e. mitmproxy) to make sure whether there is any response from server, so we can narrow down this issue.

@RodelFMiguel
Copy link
Author

@fqiu1 Happy New Year!

I am going to try some debug tool (like mitmproxy), but just for curiosity and just wondering if tcpdump will give some insights to the protocol when calling sgx_ra_get_msg1. From the packet capture below, it seems there's no problem when we are communicating with the service: ps.sgx.trustedservices.intel.com. Also, there seems to be an Expect: 100-continue that did not continue further at the end of the packet capture. There seems to be a handshake towards the end where our server machine did not reply to. I hope this can give some insight to the issue.

Thanks a lot!

Kind Regards,
Rodel

Here's the packet capture:

#####:~/Projects/ADV/attestation/ra_master$ sudo tcpdump -i eno1 port 80 -vv
tcpdump: listening on eno1, link-type EN10MB (Ethernet), capture size 262144 bytes
15:39:58.883672 IP (tos 0x0, ttl 64, id 21455, offset 0, flags [DF], proto TCP (6), length 60)
#####.44872 > ec2-54-84-191-123.compute-1.amazonaws.com.http: Flags [S], cksum 0xb862 (incorrect -> 0x7227), seq 1470888107, win 29200, options [mss 1460,sackOK,TS val 4238180 ecr 0,nop,wscale 7], length 0
15:39:58.885539 IP (tos 0x0, ttl 58, id 0, offset 0, flags [DF], proto TCP (6), length 52)
ec2-54-84-191-123.compute-1.amazonaws.com.http > #####.44872: Flags [S.], cksum 0xbc31 (correct), seq 2289762334, ack 1470888108, win 29200, options [mss 1460,nop,nop,sackOK,nop,wscale 8], length 0
15:39:58.885590 IP (tos 0x0, ttl 64, id 21456, offset 0, flags [DF], proto TCP (6), length 40)
#####.44872 > ec2-54-84-191-123.compute-1.amazonaws.com.http: Flags [.], cksum 0xb84e (incorrect -> 0x6e30), seq 1, ack 1, win 229, length 0
15:39:58.885696 IP (tos 0x0, ttl 64, id 21457, offset 0, flags [DF], proto TCP (6), length 219)
#####.44872 > ec2-54-84-191-123.compute-1.amazonaws.com.http: Flags [P.], cksum 0xb901 (incorrect -> 0xca39), seq 1:180, ack 1, win 229, length 179: HTTP, length: 179
POST / HTTP/1.1
Host: ps.sgx.trustedservices.intel.com
Accept: /
Content-Length: 38
Content-Type: application/x-www-form-urlencoded

0202754012066C4D54970000000006EQEAAgAI[!http]

15:39:58.887752 IP (tos 0x0, ttl 58, id 29475, offset 0, flags [DF], proto TCP (6), length 40)
ec2-54-84-191-123.compute-1.amazonaws.com.http > #####.44872: Flags [.], cksum 0x6deb (correct), seq 1, ack 180, win 119, length 0
15:39:59.439011 IP (tos 0x0, ttl 58, id 29476, offset 0, flags [DF], proto TCP (6), length 1496)
ec2-54-84-191-123.compute-1.amazonaws.com.http > #####.44872: Flags [P.], cksum 0x72cd (correct), seq 1:1457, ack 180, win 119, length 1456: HTTP, length: 1456
HTTP/1.1 200 OK
Date: Tue, 02 Jan 2018 07:39:59 GMT
Content-Type: text/plain
Content-Length: 1282
Connection: keep-alive
Request-ID: 99b0defc2604435bbb68ef52a9bd839b

0202754012066C4D54970100000000000003A5EgEALAAAaHR0cDovL3BzLnNneC50cnVzdGVkc2VydmljZXMuaW50ZWwuY29tOjgwFgEBgQQwYU7KMyN7SKOm5hgy9o1ZK3QOlhPzcdKlls/WfZ/b5bPVSzBnA+LYNRLp1Z3h5pntCycDoTUk6pDWooCEK5qv2DGRu4/8fVUggT/3XHy/deNiLaPHT0PUkh6I+9+jYQ4LgbKwvDZzjsgiS4IgEBUza41wSEGLp6ZHzmtP9kw4BD3nQ0EwtNC3Do0gtwlt/+vOYpSUw1V9fOgxeQIOzvOZiXPCjyC/bMb8LPQffiNkRkE1J/8Kx8nCw5so7Tdfjw5qQWoCNwSNm52sOoF833U0sgv/b7YpTPxTEMnSBludPhUa9KJNE6gLR8EhOgVn/JS4KSjkHokEaX/38DYMrc6B9s/t4pJAFtr0b1VGLCrE5a8JQtGVJCJfnb/JPEfJe6US7AZTnEQRJVe6+TQuIexLjMC9CeFvTpMVXfDBGKzxcEz64zqbWONGLMPWguLzW6oNMGtgmFRBD/sT8pGIc6NIUs1BO2t7G7hsOo2fpu8J9XiHG7O2YRTe84C7cuVdLaIXAgHspEll/ekZOwoDpasH7rwINB2Er3161GRljzAf5Ixht4Ue3VqdWnVUN9Vxs1OMUHXimX2weY0sqguy5DYdqzsjdSEnjD+uHJUPbk1bPbWhezQeQC5gpYRL4Q9FZk8ppkpDYXh4YEFND+IV2b6wEINSW2C6XhyNErLhZ6KBBxPT5TPjX7wJb43/lJneAVShzU6JS9fr+YB8XbBtNSLyR4DiujaQYruVueSJU/rE+tw74P4PMz0KcBq8J9qJYhzhqS+au+0IpOea5hEgwRWHHyGjX7cHNoZ7+QLeRCoEa5Z+B6p4vH6ebvk6JRLe/RiXc5X8IH+ngpnz+/ig6XP8gG+kqWFRtIexgcurvywr44lQImVdn/ISwwmhzu2P0wo5IVogQWrZMgFO6xiipnX+gWWuTbwfQ0SZ8hv2zozVtItYCoRmha3qGw3OirFLHRVad4DlSCb6/qZ/sdJ3Gwc5VVFSOB/YR/yIAKACCexBu3FRaDI27/9Sf9gXw1xVAtnyjavBAAEAAQAAAAAAAAAAAAAAAAAAAAAAAAAAbk1eNKVXwBVSex6aWTS7bfkMOj3Kj2Y78yHMX7MqExBuKIQx+/F9kVhsog2V7efs6M31baAIbbIrF4jOoCDoGTSVbqhl+WkgUDram5GsIIu+kZ2s[!http]

15:39:59.439055 IP (tos 0x0, ttl 64, id 21458, offset 0, flags [DF], proto TCP (6), length 40)
#####.44872 > ec2-54-84-191-123.compute-1.amazonaws.com.http: Flags [.], cksum 0xb84e (incorrect -> 0x67b7), seq 180, ack 1457, win 251, length 0
15:39:59.439191 IP (tos 0x0, ttl 64, id 21459, offset 0, flags [DF], proto TCP (6), length 40)
#####.44872 > ec2-54-84-191-123.compute-1.amazonaws.com.http: Flags [F.], cksum 0xb84e (incorrect -> 0x67b6), seq 180, ack 1457, win 251, length 0
15:39:59.440484 IP (tos 0x0, ttl 58, id 29477, offset 0, flags [DF], proto TCP (6), length 40)
ec2-54-84-191-123.compute-1.amazonaws.com.http > #####.44872: Flags [F.], cksum 0x6839 (correct), seq 1457, ack 181, win 119, length 0
15:39:59.440513 IP (tos 0x0, ttl 64, id 21460, offset 0, flags [DF], proto TCP (6), length 40)
#####.44872 > ec2-54-84-191-123.compute-1.amazonaws.com.http: Flags [.], cksum 0xb84e (incorrect -> 0x67b5), seq 181, ack 1458, win 251, length 0
15:40:00.981032 IP (tos 0x0, ttl 64, id 63927, offset 0, flags [DF], proto TCP (6), length 60)
#####.44874 > ec2-54-84-191-123.compute-1.amazonaws.com.http: Flags [S], cksum 0xb862 (incorrect -> 0xbc92), seq 2937476295, win 29200, options [mss 1460,sackOK,TS val 4238704 ecr 0,nop,wscale 7], length 0
15:40:00.982231 IP (tos 0x0, ttl 58, id 0, offset 0, flags [DF], proto TCP (6), length 52)
ec2-54-84-191-123.compute-1.amazonaws.com.http > #####.44874: Flags [S.], cksum 0xcda3 (correct), seq 1793349818, ack 2937476296, win 29200, options [mss 1460,nop,nop,sackOK,nop,wscale 8], length 0
15:40:00.982284 IP (tos 0x0, ttl 64, id 63928, offset 0, flags [DF], proto TCP (6), length 40)
#####.44874 > ec2-54-84-191-123.compute-1.amazonaws.com.http: Flags [.], cksum 0xb84e (incorrect -> 0x7fa2), seq 1, ack 1, win 229, length 0
15:40:00.982409 IP (tos 0x0, ttl 64, id 63929, offset 0, flags [DF], proto TCP (6), length 205)
#####.44874 > ec2-54-84-191-123.compute-1.amazonaws.com.http: Flags [P.], cksum 0xb8f3 (incorrect -> 0x761a), seq 1:166, ack 1, win 229, length 165: HTTP, length: 165
POST / HTTP/1.1
Host: ps.sgx.trustedservices.intel.com
Accept: /
Content-Length: 1158
Content-Type: application/x-www-form-urlencoded
Expect: 100-continue

15:40:00.983783 IP (tos 0x0, ttl 58, id 51945, offset 0, flags [DF], proto TCP (6), length 40)
ec2-54-84-191-123.compute-1.amazonaws.com.http > #####.44874: Flags [.], cksum 0x7f6b (correct), seq 1, ack 166, win 119, length 0
15:40:01.982767 IP (tos 0x0, ttl 64, id 63930, offset 0, flags [DF], proto TCP (6), length 1198)
#####.44874 > ec2-54-84-191-123.compute-1.amazonaws.com.http: Flags [P.], cksum 0xbcd4 (incorrect -> 0x3479), seq 166:1324, ack 1, win 229, length 1158: HTTP
15:40:01.984043 IP (tos 0x0, ttl 58, id 51946, offset 0, flags [DF], proto TCP (6), length 40)
ec2-54-84-191-123.compute-1.amazonaws.com.http > #####.44874: Flags [.], cksum 0x7adc (correct), seq 1, ack 1324, win 128, length 0
15:40:02.218786 IP (tos 0x0, ttl 58, id 51947, offset 0, flags [DF], proto TCP (6), length 65)
ec2-54-84-191-123.compute-1.amazonaws.com.http > #####.44874: Flags [P.], cksum 0x44a8 (correct), seq 1:26, ack 1324, win 128, length 25: HTTP, length: 25
HTTP/1.1 100 Continue

15:40:02.218827 IP (tos 0x0, ttl 64, id 63931, offset 0, flags [DF], proto TCP (6), length 40)
#####.44874 > ec2-54-84-191-123.compute-1.amazonaws.com.http: Flags [.], cksum 0xb84e (incorrect -> 0x7a5e), seq 1324, ack 26, win 229, length 0
15:40:32.220680 IP (tos 0x0, ttl 58, id 51948, offset 0, flags [DF], proto TCP (6), length 40)
ec2-54-84-191-123.compute-1.amazonaws.com.http > #####.44874: Flags [F.], cksum 0x7ac2 (correct), seq 26, ack 1324, win 128, length 0
15:40:32.220836 IP (tos 0x0, ttl 64, id 63932, offset 0, flags [DF], proto TCP (6), length 40)
#####.44874 > ec2-54-84-191-123.compute-1.amazonaws.com.http: Flags [F.], cksum 0xb84e (incorrect -> 0x7a5c), seq 1324, ack 27, win 229, length 0
15:40:32.221881 IP (tos 0x0, ttl 58, id 51949, offset 0, flags [DF], proto TCP (6), length 40)
ec2-54-84-191-123.compute-1.amazonaws.com.http > #####.44874: Flags [.], cksum 0x7ac1 (correct), seq 27, ack 1325, win 128, length 0

@RodelFMiguel
Copy link
Author

[UPDATE] The sgx_ra_get_msg1 call works on tag sgx_v1.9 but not on sgx_v2.0 onwards.

@haitaohuang
Copy link
Contributor

[update] Actually your tcpdump shows ps.sgx.trustedservices.intel.com backend may be in AWS, not your host. But still, the logs do indicate a network issue.

Please ignore previous comments:

notice you are running in AWS environment. By any chance, is there any network resource limits set in anyof your configurations? I'm not very familiar with AWS enough to know exactly what knobs to check here. But the log shows it is likely a network issue.

@RodelFMiguel
Copy link
Author

@haitaohuang,

Thanks for your reply. However, I am certain that it is not a network issue, unless there's something new in the latest SDK/PSW when it communicates with the ps.sgx.trustedservices.intel.com server. If you can see my previous comment, with v1.9 of the SDK/PSW, I am able to do a successful remote attestation. But somewhere in between that release and the latest release, the RA doesn't work anymore. What I did is clean install the driver and the SDK/PSW and tried the RA software again.

Thank you. Please check this again with clean install on Ubuntu 14.04. Also, the RA doesn't work with any machines that I have (Lenovo T470s and Intel Server Block) and with the latest SDK/PSW (>= v2.0).

@haitaohuang
Copy link
Contributor

Can you do a tcpdump for both >=2.0 (not working) and 1.9 (working)?
Also did you try to run on Ubuntu 16.04 and if any difference?

@RodelFMiguel
Copy link
Author

@haitaohuang, I guess there's no need to do the tcpdump because I tried the latest gold release, v2.1, and everything seems to work fine. I noticed that there are lots of changes in the PSW on that version so I am thinking this issue got solved? BTW, I will keep monitoring if I ever hit the same problem again. Thank you.

@haitaohuang
Copy link
Contributor

I'm glad v2.1 worked for you. I'm not aware of anyone else reporting this issue so I don't think there is any fixes targeted for this. Anyway, glad to hear everything works now. Let us know if you hit it again.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

6 participants