I assume you read the Release

Jonathan Leroy · ‎05-25-2016

Hi,

I have an home-made HTTPS-only provisioning server using a certificate generated by Cisco CA.

Since I have upgraded my test phone to firmware version 7.6.2, the HTTPS provisioning is no longer working. The provisioning server log does not log any request from the phone (SPA514G), so I think it's an SSL certificate verification issue.

Others phones using firmware version 7.6.1 work normally.

Thanks,

Jonathan.

Jaime Valencia · ‎05-25-2016

SPAs are supported in the SMB community, might want to move your thread there.

HTH

java

if this helps, please rate

Jonathan Leroy · ‎05-25-2016

Done, Thank you Jaime.

Jonathan Leroy · ‎05-25-2016

BTW, the date/time on the phone is correct.

Dan Lukes · ‎05-25-2016

I assume you read the Release Notes of the 7.6.2 firmware (I didn't) and there's no notice related to it.

In such case ...

... turn on syslog&debug (highest level) and catch them. Catch all other network activity of affected phone, including the possible attempt to fetch provisioning.

It should disclose the true cause.

Jonathan Leroy · ‎05-25-2016

There is no notice related to HTTPS provisioning or SSL certificates in the firmware release notes.

Here's the syslog output :

May 26 02:10:43 System started: ip@192.168.0.10, reboot reason:H0
May 26 02:10:43 <my public IP address> #011subnet mask:#011255.255.255.0
May 26 02:10:43 System started: ip@192.168.0.10, reboot reason:H0
May 26 02:10:43 <my public IP address> #011gateway ip:#011192.168.0.254
May 26 02:10:43 <my public IP address> IDBG: LS, 270-4ed
May 26 02:10:43 <my public IP address> IDBG: SOK
May 26 02:10:43 <my public IP address> IDBG: st-0
May 26 02:10:43 <my public IP address> [BKpic]Loading blank background image
May 26 02:10:43 <my public IP address> [BKpic]Loading blank background image
May 26 02:10:43 PHN_new.... 
May 26 02:10:43 <my public IP address> PGSK: chkcfwd in Idle key list is not defined
May 26 02:10:43 <my public IP address> PGSK: chkcfwd in Idle key list is not defined
May 26 02:10:43 <my public IP address> PGSK: chkdnd in Idle key list is not defined
May 26 02:10:43 <my public IP address> PGSK: chkdnd in Idle key list is not defined
May 26 02:10:43 <my public IP address> PGSK: chkcfwd in Progressing key list is not defined
May 26 02:10:43 <my public IP address> PGSK: chkcfwd in Progressing key list is not defined
May 26 02:10:43 <my public IP address> PGSK: chkdnd in Progressing key list is not defined
May 26 02:10:43 <my public IP address> PGSK: chkdnd in Progressing key list is not defined
May 26 02:10:43 <my public IP address> PGSK: chkcfwd in Releasing key list is not defined
May 26 02:10:43 <my public IP address> PGSK: chkcfwd in Releasing key list is not defined
May 26 02:10:43 <my public IP address> PGSK: chkdnd in Releasing key list is not defined
May 26 02:10:43 <my public IP address> PGSK: chkdnd in Releasing key list is not defined
May 26 02:10:43 <my public IP address> PGSK: chkcfwd in Hold key list is not defined
May 26 02:10:43 <my public IP address> PGSK: chkcfwd in Hold key list is not defined
May 26 02:10:43 <my public IP address> PGSK: chkdnd in Hold key list is not defined
May 26 02:10:43 <my public IP address> PGSK: chkdnd in Hold key list is not defined
May 26 02:10:44 <my public IP address> PGSK: chkcfwd in Shared Active key list is not defined
May 26 02:10:44 <my public IP address> PGSK: chkcfwd in Shared Active key list is not defined
May 26 02:10:44 <my public IP address> PGSK: chkdnd in Shared Active key list is not defined
May 26 02:10:44 <my public IP address> PGSK: chkdnd in Shared Active key list is not defined
May 26 02:10:44 <my public IP address> PGSK: chkcfwd in Shared Held key list is not defined
May 26 02:10:44 <my public IP address> PGSK: chkcfwd in Shared Held key list is not defined
May 26 02:10:44 <my public IP address> PGSK: chkdnd in Shared Held key list is not defined
May 26 02:10:44 <my public IP address> PGSK: chkdnd in Shared Held key list is not defined
May 26 02:10:44 <my public IP address> sntp_set_system_time!!! 
May 26 02:10:44 <my public IP address> sntp_set_system_time!!! 
May 26 02:10:44 <my public IP address> [create_tcp_netstrm1] use async to create tcp connection
May 26 02:11:01 <my public IP address> fs: 060643:060643:262144
May 26 02:11:01 <my public IP address> fls: fuuaffffff:14:5900:118832
May 26 02:11:01 <my public IP address> fbr: 1:3000:3000:2fe56:0016:0017:7.6.2
May 26 02:11:01 <my public IP address> fhs: 01:0:0007:upg:app:2:7.5.6a
May 26 02:11:01 <my public IP address> fhs: 02:0:0008:upg:app:0:7.5.7
May 26 02:11:01 <my public IP address> fhs: 03:0:0009:upg:app:1:7.5.7
May 26 02:11:01 <my public IP address> fhs: 04:0:000a:upg:app:2:7.5.7
May 26 02:11:01 <my public IP address> fhs: 05:0:000b:upg:app:0:7.5.7s
May 26 02:11:01 <my public IP address> fhs: 06:0:000c:upg:app:1:7.5.7s
May 26 02:11:01 <my public IP address> fhs: 07:0:000d:upg:app:2:7.5.7s
May 26 02:11:01 <my public IP address> fhs: 08:0:000e:upg:app:0:7.5.6a
May 26 02:11:01 <my public IP address> fhs: 09:0:000f:upg:app:1:7.5.6a
May 26 02:11:01 <my public IP address> fhs: 0a:0:0010:upg:app:2:7.5.6a
May 26 02:11:01 <my public IP address> fhs: 0b:0:0011:upg:app:0:7.6.1
May 26 02:11:01 <my public IP address> fhs: 0c:0:0012:upg:app:1:7.6.1
May 26 02:11:01 <my public IP address> fhs: 0d:0:0013:upg:app:2:7.6.1
May 26 02:11:01 <my public IP address> fhs: 0e:0:0014:upg:app:0:7.6.2
May 26 02:11:01 <my public IP address> fhs: 0f:0:0015:upg:app:1:7.6.2
May 26 02:11:01 <my public IP address> fhs: 10:0:0016:upg:app:2:7.6.2
May 26 02:11:01 dhcp opt 66: ""
May 26 02:11:01 dhcp opt 160: ""
May 26 02:11:01 dhcp opt 159: ""
May 26 02:11:01 dhcp opt 150: ""
May 26 02:11:01 dhcp opt 60: ""
May 26 02:11:01 dhcp opt 43: ""
May 26 02:11:01 dhcp opt 125: ""
May 26 02:11:01 <my public IP address> fu: 1:0fe70, 5.1.1 1
May 26 02:11:19 resync rule: https://sip-provisioning.inikup.com/SPA514G/common.xml?sn=CCQ174400MK&hwver=1.0.0&swver=7.6.2&prvst=0
May 26 02:11:19 resync rule: https://sip-provisioning.inikup.com/SPA514G/common.xml?sn=CCQ174400MK&hwver=1.0.0&swver=7.6.2&prvst=0
May 26 02:11:19 <my public IP address> ++ j=0 sip=b01fdeba
May 26 02:11:19 <my public IP address> ++ j=0 sip=b01fdeba
May 26 02:11:19 <my public IP address> fs: 060643:060659:262144:112011207999
May 26 02:11:19 pbs 230912 
May 26 02:11:19 SPA514G a4: 93:4c:fe:93:76 -- Requesting resync https://176.31.222.186:443/SPA514G/common.xml?sn=CCQ174400MK&hwver=1.0.0&swver=7.6.2&prvst=0
May 26 02:11:19 SPA514G a4: 93:4c:fe:93:76 -- Requesting resync https://176.31.222.186:443/SPA514G/common.xml?sn=CCQ174400MK&hwver=1.0.0&swver=7.6.2&prvst=0
May 26 02:11:19 FMM >>>> Requesting profile
May 26 02:11:19 <my public IP address> [create_tcp_netstrm1] use async to create tcp connection
May 26 02:11:19 connect succeed 
May 26 02:11:19 <my public IP address> [create_tcp_netstrm1] connect SUCCEED
May 26 02:12:31 create ssl connection failed
May 26 02:12:31 SPA514G a4: 93:4c:fe:93:76 -- Resync failed: https_get failed
May 26 02:12:31 SPA514G a4: 93:4c:fe:93:76 -- Resync failed: https_get failed
May 26 02:12:31 FMM >>>> Failed profile
May 26 02:12:31 <my public IP address> Retrying... 1
May 26 02:12:31 <my public IP address> Retrying... 1
May 26 02:12:31 <my public IP address> [create_tcp_netstrm1] use async to create tcp connection
May 26 02:12:31 connect failed 
May 26 02:12:31 connect succeed 
May 26 02:12:31 <my public IP address> [create_tcp_netstrm1] connect SUCCEED
May 26 02:13:42 create ssl connection failed
May 26 02:13:42 SPA514G a4: 93:4c:fe:93:76 -- Resync failed: https_get failed
May 26 02:13:42 SPA514G a4: 93:4c:fe:93:76 -- Resync failed: https_get failed
May 26 02:13:42 FMM >>>> Failed profile
May 26 02:13:42 <my public IP address> Retrying... 2
May 26 02:13:42 <my public IP address> Retrying... 2
May 26 02:13:42 <my public IP address> [create_tcp_netstrm1] use async to create tcp connection
May 26 02:13:43 connect succeed 
May 26 02:13:43 <my public IP address> [create_tcp_netstrm1] connect SUCCEED
May 26 02:14:54 create ssl connection failed
May 26 02:14:54 SPA514G a4: 93:4c:fe:93:76 -- Resync failed: https_get failed
May 26 02:14:54 SPA514G a4: 93:4c:fe:93:76 -- Resync failed: https_get failed
May 26 02:14:54 FMM >>>> Failed profile

Dan Lukes · ‎05-26-2016

I expected the output like the one shown in SSL errors (secure provisioning issues) document. I'm missing the "ssl cert err N" message.

It disclose either

you didn't catched some debug3 level messages
7.6.2 firmware has been modified not to disclose the verification result
there's no issue with SSL setup

OK, no conclusion possible so far. Lets another attempt. Catch the IP packets related to HTTPS attempt. But I need the binary form of captured packets - e.g. .pcap file saved from either wireshark or tcpdump. The file needs to be renamed to .txt or you will not be allowed to attach it here. If the SSL session has been rejected before it entered encrypted phase, I may be able to identify the refuse reason from it.

I assume you analyzed the SSL logs on HTTPS server side and verified there are no errors related to this HTTPS request recorded. Neither at SSL setup level nor at application level (I assume your provisioning is server by an application, e.g. it's not static file). Make sure the application is not the cause. Note the 11 seconds delay between "connect SUCCEED" and "create ssl connection failed" of your log. It's so much for initial SSL handshake.

You disclosed no authority you used for server's certificate (Cisco use four different CA to sign requests). So I assume you selected the correct one for 7.6.2 firmware.

Finally, note I have no SPA514G here, so I can't try to reproduce the issue by self. There's no 7.6.2 firmware for SPA504G yet.

Jonathan Leroy · ‎05-26-2016

Please find the pcap file attached.

The SSL certificate has been issued by "Cisco Small Business Provisioning Root Authority 1".

It disclose either

you didn't catched some debug3 level messages

7.6.2 firmware has been modified not to disclose the verification result

there's no issue with SSL setup

Or a big bug in the latest firmware ;)

Make sure the application is not the cause. Note the 11 seconds delay between "connect SUCCEED" and "create ssl connection failed" of your log. It's so much for initial SSL handshake.

The same app works fine with firmware version 7.6.1 (provisioning ok and no delay between TCP connection and SSL handshake).

Dan Lukes · ‎05-26-2016

You may remove the file you attached (as it disclose some emails and IP addresses you may wish not to disclose) now. I extracted all necessary information here:

00.00 -> [SYN]

00.00 <- [SYN, ACK]

00.02 -> [ACK]

00.34 -> TLSv1 ClientHello

00.35 <- TLSv1 ServerHello(TLS_DHE_RSA_WITH_AES_256_CBC_SHA), Certificate

00.35 <- TLSv1 ServerKeyExchange, ServerHelloDone

60.03 <- [FIN,ACK]

71.97 -> TLSv1 ClientKeyExchange, ChangeCipherSpec, EncryptedHandhakeMessage

71.97 -> [RST]

I'm pretty sure I know the cause. Your HTTP server is so impatient.

HTTPS is cryptography. SPA5xx have not so high computing power thus it require a lot of time. In your particular case it take almost 72 seconds to compute packet #8. But your server is not willing to wait for it. It fire timeout after 60 seconds (packet #7). SSL handhake is aborted.

You should reconfigure your HTTPS server to be more patient. I wish it will solve your issue.

I should update this table as handshake of recent firmware take more time than older one.

Jonathan Leroy · ‎05-26-2016

Thank you Dan!

I've added the following directive to my Nginx config, and the provisioning process is working as expected now:

client_header_timeout 180s;

But every HTTPS connection take between 70 and 90 seconds against 15 seconds with the previous firmware version. The TLS configuration of the provisioning server hasn't changed since, so I still think there is problem with the latest firmware.

Dan Lukes · ‎05-27-2016

Well, even 90 seconds should not harm. It's about provisioning, not about the call, so user experience should not be affected.

According "there is problem with the latest firmware" - it's about the definition of the term "problem". Of course, it may be firmware bug - an un-optiomal cryptography code is so slow compared with optimized code in previous version.

But there's also other, "non-problem" cause possible.

The new firmware may just support new ciphers unsupported in previous firmware. Those new/more secure ciphers may take longer time to compute.

Phone with 7.6.2 supports following ciphers:

Catch the SSL handshaking from 7.6.1, identify the cipher used by this version, then tweak NGINX to select this cipher. I suspect the *_DHE_* kind of ciphers mau cause it - it take time to generate 1024b of DH Public Key. So try a non _DHE_ cipher instead.

Just hypothesis, of course. Just try.

Jonathan Leroy · ‎03-29-2017

FYI, firmware version 7.6.2SR2 solve this problem. I haven't tested version 7.6.2SR1.

Dan Lukes · ‎03-30-2017

There's simple solution to speed-up it (if issue has been caused by DH pair code). Device may not generate own DH pair, but may use the constant one. Or the _DHE_ ciphers has been deprioritised or disabled at all.

Unfortunately, no word about it in release notes. Thus no way to evaluate security consequences of the change. We don't know if the "secure provisioning" is still secure enough, or it just mimics security.

SPA514G : HTTPS provisioning no longer working since upgrading to fw 7.6.2