Buy or Renew
Buy or Renew
cancel
Turn on suggestions
Auto-suggest helps you quickly narrow down your search results by suggesting possible matches as you type.
Showing results for 
Search instead for 
Did you mean: 
cancel
Start a conversation
1249
Views
0
Helpful
3
Replies

Cisco/SPA112-1.4.1SR1(002) Hangs after a few successful attempts to download a profile

kp1893612
Level 1
Level 1

‎03-05-2019 01:39 PM - edited ‎03-06-2019 10:08 AM

  • Brand new device (purchased from Amazon)
  • Firmware upgraded to 1.4.1SR1(002)
  • Factory reset
  • Profile_Rule set using /admin/resync?http://server/init.cfg
  • Some parameters are set including Profile_Rule_B, Profile_Rule_C, etc (all configs pasted below)
  • Device successfully downloads and applies all profiles numerous times (HTTP code 200)
  • After a few repeated cycles of what was previously successful, it will attempt the first profile (Profile_Rule) based on the resync interval set and just hang.
  • Web UI unresponsive, IVR unresponsive
  • Power light solid green, Network light showing activity
  • URL commands no longer work (e.g. /admin/reboot)
  • Power cycle fixes issue until it recurs. Device also reboots by itself after exactly 1 hour of being hung.
  • Network traffic at the time of issue shows TCP retransmissions on the HTTP conversation. However it is not clear whether this is the cause of the issue, or a symptom of the device being hung.
  • Issue is not present on firmware Cisco/SPA112-1.3.5(004p). Profile downloads worked every 60 seconds for more than an hour without an problems. Tested on a 2nd device preloaded with that firmware -- no issue. Downgraded from 1.4.1SR1(002) on the device that caused us to open this thread -- no issue afterwards.
  • Conclusion: Unless Cisco provides any info to the contrary, there is definitely a bug in 1.4.1SR1(002) that causes the device to hang for an unknown reason.

Contents of init.cfg:

<flat-profile>
<GPP_P>6F3FCA8C-8C78-4870-8FAC-xxx</GPP_P>
<Profile_Rule>http://xxx/fix.cfg</Profile_Rule>
<Profile_Rule_B>http://xxx/default.cfg</Profile_Rule_B>
<Resync_Error_Retry_Delay>10</Resync_Error_Retry_Delay>
<Resync_Fails_On_FNF>No</Resync_Fails_On_FNF>
<Resync_Periodic>10</Resync_Periodic>
<Syslog_Prefix>$SN</Syslog_Prefix>
<Syslog_Server>x.x.x.x:20241</Syslog_Server>
<Debug_Server>x.x.x.x:20241</Debug_Server>
<Debug_Level>3</Debug_Level>
<Upgrade_Rule ua="na">("$SWVER" ne "1.4.1SR1(002)")?http://xxx/firmware/Payton_1.4.1SR1_002_080217_1439_pfmwr.bin</Upgrade_Rule>
</flat-profile>

Contents of fix.cfg it gets stuck on:

<flat-profile>
<GPP_O>fix.cfg</GPP_O>
</flat-profile>

Contents of default.cfg:

<flat-profile>
<GPP_P>0698F65E-4407-4FC0-B4A6-xxxxxxxxxxxxxxx</GPP_P>
<Profile_Rule_C>http://xxx/cgi-bin/log.py?SERIAL_NUMBER=$SN&amp;MAC_ADDRESS=$MAU&amp;GPP_A=$A&amp;GPP_B=$B&amp;GPP_C=$C&amp;GPP_D=$D&amp;GPP_E=$E&amp;GPP_F=$F&amp;GPP_G=$G&amp;GPP_H=$H&amp;GPP_I=$I&amp;GPP_J=$J&amp;GPP_K=$K&amp;GPP_L=$L&amp;GPP_M=$M&amp;GPP_N=$N&amp;GPP_O=$O&amp;GPP_P=$P&amp;IP=$IP&amp;EXTIP=$EXTIP&amp;SWVER=$SWVER&amp;HWVER=$HWVER&amp;PRVST=$PRVST&amp;UPGST=$UPGST&amp;PRVTMR=$PRVTMR&amp;UPGTMR=$UPGTMR&amp;REGTMR1=$REGTMR1&amp;REGTMR2=$REGTMR2</Profile_Rule_C>
<Resync_Error_Retry_Delay>900</Resync_Error_Retry_Delay>
<Resync_Periodic>900</Resync_Periodic>
</flat-profile>

 

Previous successful resync:

Mar 05 14:48:46 x.x.x.x logger: CCQ21350A79 ################# CC: running... ############ 
Mar 05 14:49:08 x.x.x.x logger: CCQ21350A79 PRV pc=2 
Mar 05 14:49:08 x.x.x.x logger: CCQ21350A79 fs:066927:067112:262144:130026287999 
Mar 05 14:49:08 x.x.x.x logger: CCQ21350A79 pbs 256512 
Mar 05 14:49:08 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Requesting resync http://x.x.x.x:80/fix.cfg 
Mar 05 14:49:08 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Requesting resync http://x.x.x.x:80/fix.cfg 
Mar 05 14:49:08 x.x.x.x logger: CCQ21350A79 FMM >>>> Requesting profile 
Mar 05 14:49:08 x.x.x.x logger: CCQ21350A79 [_fprv_download_file] get dn_schema 2 path=/fix.cfg ip 54,156,10,53 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 response_status = 200 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 content len (hdr) =54 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 content len (pld) =54 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 response code =200 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 Firmware downgrade limit() 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Successful resync http://x.x.x.x:80/fix.cfg 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Successful resync http://x.x.x.x:80/fix.cfg 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 FMM >>>> Successful profile 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 fs:066927:067112:262144:098426287999 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 pbs 256512 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Requesting resync http://x.x.x.x:80/default.cfg 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Requesting resync http://x.x.x.x:80/default.cfg 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 FMM >>>> Requesting profile 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 [_fprv_download_file] get dn_schema 2 path=/default.cfg ip 54,156,10,53 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 response_status = 200 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 content len (hdr) =677 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 content len (pld) =677 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 response code =200 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 Firmware downgrade limit() 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Successful resync http://x.x.x.x:80/default.cfg 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Successful resync http://x.x.x.x:80/default.cfg 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 FMM >>>> Successful profile 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 fs:066927:067112:262144:263226327999 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 pbs 256512 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Requesting resync http://x.x.x.x:80/cgi-bin/log.py?SERIAL_NUMBER=CCQ21350A79&MAC_ADDRESS=00A2895B4D4C&GPP_A=&GPP_B=&GPP_C=&GPP_D=&GPP_E=&GPP_F=&GPP_G=&GPP_H=&GPP_I=&GPP_J=&GPP_K=&GPP_L=&GPP_M=&GPP_N=log.py&GPP_O=fix.cfg&GPP_P=0698F65E-4407-4FC0-B4A6-8776C8CD2EC7&IP=10.0.1.152&EXTIP=&SWVER=1.4.1SR1(002)&HWVER=1.1.0&PRVST=1&UPGST=1&PRVTMR=900&UPGTMR=11316&REGTMR1=1861&REGTMR2=1861 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Requesting resync http://x.x.x.x:80/cgi-bin/log.py?SERIAL_NUMBER=CCQ21350A79&MAC_ADDRESS=00A2895B4D4C&GPP_A=&GPP_B=&GPP_C=&GPP_D=&GPP_E=&GPP_F=&GPP_G=&GPP_H=&GPP_I=&GPP_J=&GPP_K=&GPP_L=&GPP_M=&GPP_N=log.py&GPP_O=fix.cfg&GPP_P=0698F65E-4407-4FC0-B4A6-8776C8CD2EC7&IP=10.0.1.152&EXTIP=&SWVER=1.4.1SR1(002)&HWVER=1.1.0&PRVST=1&UPGST=1&PRVTMR=900&UPGTMR=11316&REGTMR1=1861&REGTMR2=1861 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 FMM >>>> Requesting profile 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 [_fprv_download_file] get dn_schema 2 path=/cgi-bin/log.py?SERIAL_NUMBER=CCQ21350A79&MAC_ADDRESS=00A2895B4D4C&GPP_A=&GPP_B=&GPP_C=&GPP_D=&GPP_E=&GPP_F=&GPP_G=&GPP_H=&GPP_I=&GPP_J=&GPP_K=&GPP_L=&GPP_M=&GPP_N=log.py&GPP_O=fix.cfg&GPP_P=0698F65E-4407-4FC0-B4A6-8776C8CD2EC7&IP=10.0.1.152&EXTIP=&SWVER=1.4.1SR1(002)&HWVER=1.1.0&PRVST=1&UPGST=1&PRVTMR=900&UPGTMR=11316&REGTMR1=1861&REGTMR2=1861 ip 54,156,10,53 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 response_status = 200 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 content len (hdr) =51 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 content len (pld) =51 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 response code =200 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 Firmware downgrade limit() 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Successful resync http://x.x.x.x:80/cgi-bin/log.py?SERIAL_NUMBER=CCQ21350A79&MAC_ADDRESS=00A2895B4D4C&GPP_A=&GPP_B=&GPP_C=&GPP_D=&GPP_E=&GPP_F=&GPP_G=&GPP_H=&GPP_I=&GPP_J=&GPP_K=&GPP_L=&GPP_M=&GPP_N=log.py&GPP_O=fix.cfg&GPP_P=0698F65E-4407-4FC0-B4A6-8776C8CD2EC7&IP=10.0.1.152&EXTIP=&SWVER=1.4.1SR1(002)&HWVER=1.1.0&PRVST=1&UPGST=1&PRVTMR=900&UPGTMR=11316&REGTMR1=1861&REGTMR2=1861 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Successful resync http://x.x.x.x:80/cgi-bin/log.py?SERIAL_NUMBER=CCQ21350A79&MAC_ADDRESS=00A2895B4D4C&GPP_A=&GPP_B=&GPP_C=&GPP_D=&GPP_E=&GPP_F=&GPP_G=&GPP_H=&GPP_I=&GPP_J=&GPP_K=&GPP_L=&GPP_M=&GPP_N=log.py&GPP_O=fix.cfg&GPP_P=0698F65E-4407-4FC0-B4A6-8776C8CD2EC7&IP=10.0.1.152&EXTIP=&SWVER=1.4.1SR1(002)&HWVER=1.1.0&PRVST=1&UPGST=1&PRVTMR=900&UPGTMR=11316&REGTMR1=1861&REGTMR2=1861 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 FMM >>>> Successful profile 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 [profile_param_tbl_show] 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 [profile_param_tbl_show] total size (40360 + 0) = 40360 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 [profile_update_flash] 3993 usec 
Mar 05 14:49:09 x.x.x.x logger: CCQ21350A79 [profile_update_flash] need_reboot 0x0

 Successful resync right before problem:

Mar 05 14:53:46 x.x.x.x logger: CCQ21350A79 ################# CC: running... ############ 
Mar 05 14:58:46 x.x.x.x logger: CCQ21350A79 ################# CC: running... ############ 
Mar 05 15:03:46 x.x.x.x logger: CCQ21350A79 ################# CC: running... ############ 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 PRV pc=3 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 fs:066927:067112:262144:130026447999 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 pbs 256512 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Requesting resync http://x.x.x.x:80/fix.cfg 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Requesting resync http://x.x.x.x:80/fix.cfg 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 FMM >>>> Requesting profile 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 [_fprv_download_file] get dn_schema 2 path=/fix.cfg ip 54,156,10,53 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 response_status = 200 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 content len (hdr) =54 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 content len (pld) =54 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 response code =200 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 Firmware downgrade limit() 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Successful resync http://x.x.x.x:80/fix.cfg 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Successful resync http://x.x.x.x:80/fix.cfg 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 FMM >>>> Successful profile 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 fs:066927:067112:262144:098426447999 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 pbs 256512 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Requesting resync http://x.x.x.x:80/default.cfg 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Requesting resync http://x.x.x.x:80/default.cfg 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 FMM >>>> Requesting profile 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 [_fprv_download_file] get dn_schema 2 path=/default.cfg ip 54,156,10,53 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 response_status = 200 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 content len (hdr) =677 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 content len (pld) =677 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 response code =200 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 Firmware downgrade limit() 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Successful resync http://x.x.x.x:80/default.cfg 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Successful resync http://x.x.x.x:80/default.cfg 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 FMM >>>> Successful profile 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 fs:066927:067112:262144:263226447999 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 pbs 256512 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Requesting resync http://x.x.x.x:80/cgi-bin/log.py?SERIAL_NUMBER=CCQ21350A79&MAC_ADDRESS=00A2895B4D4C&GPP_A=&GPP_B=&GPP_C=&GPP_D=&GPP_E=&GPP_F=&GPP_G=&GPP_H=&GPP_I=&GPP_J=&GPP_K=&GPP_L=&GPP_M=&GPP_N=log.py&GPP_O=fix.cfg&GPP_P=0698F65E-4407-4FC0-B4A6-8776C8CD2EC7&IP=10.0.1.152&EXTIP=&SWVER=1.4.1SR1(002)&HWVER=1.1.0&PRVST=1&UPGST=1&PRVTMR=900&UPGTMR=12216&REGTMR1=2761&REGTMR2=2761 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Requesting resync http://x.x.x.x:80/cgi-bin/log.py?SERIAL_NUMBER=CCQ21350A79&MAC_ADDRESS=00A2895B4D4C&GPP_A=&GPP_B=&GPP_C=&GPP_D=&GPP_E=&GPP_F=&GPP_G=&GPP_H=&GPP_I=&GPP_J=&GPP_K=&GPP_L=&GPP_M=&GPP_N=log.py&GPP_O=fix.cfg&GPP_P=0698F65E-4407-4FC0-B4A6-8776C8CD2EC7&IP=10.0.1.152&EXTIP=&SWVER=1.4.1SR1(002)&HWVER=1.1.0&PRVST=1&UPGST=1&PRVTMR=900&UPGTMR=12216&REGTMR1=2761&REGTMR2=2761 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 FMM >>>> Requesting profile 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 [_fprv_download_file] get dn_schema 2 path=/cgi-bin/log.py?SERIAL_NUMBER=CCQ21350A79&MAC_ADDRESS=00A2895B4D4C&GPP_A=&GPP_B=&GPP_C=&GPP_D=&GPP_E=&GPP_F=&GPP_G=&GPP_H=&GPP_I=&GPP_J=&GPP_K=&GPP_L=&GPP_M=&GPP_N=log.py&GPP_O=fix.cfg&GPP_P=0698F65E-4407-4FC0-B4A6-8776C8CD2EC7&IP=10.0.1.152&EXTIP=&SWVER=1.4.1SR1(002)&HWVER=1.1.0&PRVST=1&UPGST=1&PRVTMR=900&UPGTMR=12216&REGTMR1=2761&REGTMR2=2761 ip 54,156,10,53 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 response_status = 200 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 chunked content len (pld) =51 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 response code =200 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 Firmware downgrade limit() 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Successful resync http://x.x.x.x:80/cgi-bin/log.py?SERIAL_NUMBER=CCQ21350A79&MAC_ADDRESS=00A2895B4D4C&GPP_A=&GPP_B=&GPP_C=&GPP_D=&GPP_E=&GPP_F=&GPP_G=&GPP_H=&GPP_I=&GPP_J=&GPP_K=&GPP_L=&GPP_M=&GPP_N=log.py&GPP_O=fix.cfg&GPP_P=0698F65E-4407-4FC0-B4A6-8776C8CD2EC7&IP=10.0.1.152&EXTIP=&SWVER=1.4.1SR1(002)&HWVER=1.1.0&PRVST=1&UPGST=1&PRVTMR=900&UPGTMR=12216&REGTMR1=2761&REGTMR2=2761 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Successful resync http://x.x.x.x:80/cgi-bin/log.py?SERIAL_NUMBER=CCQ21350A79&MAC_ADDRESS=00A2895B4D4C&GPP_A=&GPP_B=&GPP_C=&GPP_D=&GPP_E=&GPP_F=&GPP_G=&GPP_H=&GPP_I=&GPP_J=&GPP_K=&GPP_L=&GPP_M=&GPP_N=log.py&GPP_O=fix.cfg&GPP_P=0698F65E-4407-4FC0-B4A6-8776C8CD2EC7&IP=10.0.1.152&EXTIP=&SWVER=1.4.1SR1(002)&HWVER=1.1.0&PRVST=1&UPGST=1&PRVTMR=900&UPGTMR=12216&REGTMR1=2761&REGTMR2=2761 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 FMM >>>> Successful profile 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 [profile_param_tbl_show] 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 [profile_param_tbl_show] total size (40360 + 0) = 40360 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 [profile_update_flash] 3988 usec 
Mar 05 15:04:09 x.x.x.x logger: CCQ21350A79 [profile_update_flash] need_reboot 0x0

Failed resync on "response_status = 200" line (Line #11) and subsequent power cycle:

Mar 05 15:08:46 x.x.x.x logger: CCQ21350A79 ################# CC: running... ############ 
Mar 05 15:13:46 x.x.x.x logger: CCQ21350A79 ################# CC: running... ############ 
Mar 05 15:18:46 x.x.x.x logger: CCQ21350A79 ################# CC: running... ############ 
Mar 05 15:19:09 x.x.x.x logger: CCQ21350A79 PRV pc=4 
Mar 05 15:19:09 x.x.x.x logger: CCQ21350A79 fs:066927:067112:262144:130026447999 
Mar 05 15:19:09 x.x.x.x logger: CCQ21350A79 pbs 256512 
Mar 05 15:19:09 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Requesting resync http://x.x.x.x:80/fix.cfg 
Mar 05 15:19:09 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Requesting resync http://x.x.x.x:80/fix.cfg 
Mar 05 15:19:09 x.x.x.x logger: CCQ21350A79 FMM >>>> Requesting profile 
Mar 05 15:19:09 x.x.x.x logger: CCQ21350A79 [_fprv_download_file] get dn_schema 2 path=/fix.cfg ip 54,156,10,53 
Mar 05 15:19:09 x.x.x.x logger: CCQ21350A79 response_status = 200 
Mar 05 16:19:10 x.x.x.x logger: CCQ21350A79 system halt:src/flashfmm.c:973 
Mar 05 16:20:03 x.x.x.x logger: CCQ21350A79 System started: ip@10.0.1.152, reboot reason:H0 
Mar 05 16:20:03 x.x.x.x logger: CCQ21350A79 subnet mask: 255.255.255.0 
Mar 05 16:20:03 x.x.x.x logger: CCQ21350A79 gateway ip: 10.0.1.1 
Mar 05 16:20:03 x.x.x.x logger: CCQ21350A79 SCAPC_init(): provision_enable=1 prule=http://xxx/fix.cfg tftp=10.0.1.75 
Mar 05 16:20:03 x.x.x.x logger: CCQ21350A79 Boot up random delay: 
Mar 05 16:20:03 x.x.x.x logger: CCQ21350A79 Boot up random delay: 
Mar 05 16:20:03 x.x.x.x logger: CCQ21350A79 going to sleep 60 csec 
Mar 05 16:20:03 x.x.x.x logger: CCQ21350A79 going to sleep 60 csec 
Mar 05 16:20:05 x.x.x.x logger: CCQ21350A79 [SCAPC]WaitTime:10 
Mar 05 16:20:05 x.x.x.x logger: CCQ21350A79 [SCAPC]WaitTime:10 
Mar 05 16:20:06 x.x.x.x logger: CCQ21350A79 [SCAPC]WaitTime:20 
Mar 05 16:20:06 x.x.x.x logger: CCQ21350A79 [SCAPC]WaitTime:20 
Mar 05 16:20:07 x.x.x.x logger: CCQ21350A79 [SCAPC]WaitTime:40 
Mar 05 16:20:07 x.x.x.x logger: CCQ21350A79 [SCAPC]WaitTime:40 
Mar 05 16:20:08 x.x.x.x logger: CCQ21350A79 [SCAPC]WaitTime:80 
Mar 05 16:20:08 x.x.x.x logger: CCQ21350A79 [SCAPC]WaitTime:80 
Mar 05 16:20:08 x.x.x.x logger: CCQ21350A79 [LVS]Cannot resolve LVS_PROXY. Read lvs address from flash. IP = 
Mar 05 16:20:08 x.x.x.x logger: CCQ21350A79 uch_syncParameter start 
Mar 05 16:20:08 x.x.x.x logger: CCQ21350A79 uchInitDTMFTbl(), fxs dtmf level -160 twist 20 
Mar 05 16:20:08 x.x.x.x logger: CCQ21350A79 uchEnableEchoCan(), lid 0 EP 2 enable 
Mar 05 16:20:08 x.x.x.x logger: CCQ21350A79 UCH sync parameter hold off time is 70 
Mar 05 16:20:08 x.x.x.x logger: CCQ21350A79 uch_syncParameter(), uch_syncDTMFHoldOffTime(0)=0 
Mar 05 16:20:08 x.x.x.x logger: CCQ21350A79 uchEnableEchoCan(), lid 1 EP 1 enable 
Mar 05 16:20:08 x.x.x.x logger: CCQ21350A79 UCH sync parameter hold off time is 70 
Mar 05 16:20:08 x.x.x.x logger: CCQ21350A79 uch_syncParameter(), uch_syncDTMFHoldOffTime(1)=0 
Mar 05 16:20:08 x.x.x.x logger: CCQ21350A79 sysstatus_set_led_status_payton(), led_id: 0, statusCode:0, systemEvent: 0xfffe 
Mar 05 16:20:08 x.x.x.x logger: CCQ21350A79 sysstatus_set_led_status_payton(), led_id: 1, statusCode:0, systemEvent: 0xfffe 
Mar 05 16:20:08 x.x.x.x logger: CCQ21350A79 sysstatus_set_led_status_payton(), led_id: 2, statusCode:0, systemEvent: 0xfffe 
Mar 05 16:20:15 x.x.x.x logger: CCQ21350A79 fs:066927:067112:262144:087210927999 
Mar 05 16:20:15 x.x.x.x logger: CCQ21350A79 pbs 256512 
Mar 05 16:20:15 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Requesting resync http://x.x.x.x:80/fix.cfg 
Mar 05 16:20:15 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Requesting resync http://x.x.x.x:80/fix.cfg 
Mar 05 16:20:15 x.x.x.x logger: CCQ21350A79 FMM >>>> Requesting profile 
Mar 05 16:20:15 x.x.x.x logger: CCQ21350A79 [_fprv_download_file] get dn_schema 2 path=/fix.cfg ip 54,156,10,53 
Mar 05 16:20:15 x.x.x.x logger: CCQ21350A79 response_status = 200 
Mar 05 16:20:15 x.x.x.x logger: CCQ21350A79 content len (hdr) =54 
Mar 05 16:20:15 x.x.x.x logger: CCQ21350A79 content len (pld) =54 
Mar 05 16:20:15 x.x.x.x logger: CCQ21350A79 response code =200 
Mar 05 16:20:15 x.x.x.x logger: CCQ21350A79 Firmware downgrade limit() 
Mar 05 16:20:15 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Successful resync http://x.x.x.x:80/fix.cfg 
Mar 05 16:20:15 x.x.x.x logger: CCQ21350A79 fs:066927:067112:262144:097610927999 
Mar 05 16:20:15 x.x.x.x logger: CCQ21350A79 pbs 256512 
Mar 05 16:20:15 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Requesting resync http://x.x.x.x:80/default.cfg 
Mar 05 16:20:15 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Requesting resync http://x.x.x.x:80/default.cfg 
Mar 05 16:20:15 x.x.x.x logger: CCQ21350A79 FMM >>>> Requesting profile 
Mar 05 16:20:15 x.x.x.x logger: CCQ21350A79 [_fprv_download_file] get dn_schema 2 path=/default.cfg ip 54,156,10,53 
Mar 05 16:20:15 x.x.x.x logger: CCQ21350A79 response_status = 200 
Mar 05 16:20:15 x.x.x.x logger: CCQ21350A79 content len (hdr) =677 
Mar 05 16:20:15 x.x.x.x logger: CCQ21350A79 content len (pld) =677 
Mar 05 16:20:15 x.x.x.x logger: CCQ21350A79 response code =200 
Mar 05 16:20:15 x.x.x.x logger: CCQ21350A79 Firmware downgrade limit() 
Mar 05 16:20:15 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Successful resync http://x.x.x.x:80/default.cfg 
Mar 05 16:20:15 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Successful resync http://x.x.x.x:80/default.cfg 
Mar 05 16:20:15 x.x.x.x logger: CCQ21350A79 FMM >>>> Successful profile 
Mar 05 16:20:15 x.x.x.x logger: CCQ21350A79 fs:066927:067112:262144:260026007999 
Mar 05 16:20:15 x.x.x.x logger: CCQ21350A79 pbs 256512 
Mar 05 16:20:15 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Requesting resync http://x.x.x.x:80/cgi-bin/log.py?SERIAL_NUMBER=CCQ21350A79&MAC_ADDRESS=00A2895B4D4C&GPP_A=&GPP_B=&GPP_C=&GPP_D=&GPP_E=&GPP_F=&GPP_G=&GPP_H=&GPP_I=&GPP_J=&GPP_K=&GPP_L=&GPP_M=&GPP_N=log.py&GPP_O=fix.cfg&GPP_P=0698F65E-4407-4FC0-B4A6-8776C8CD2EC7&IP=10.0.1.152&EXTIP=&SWVER=1.4.1SR1(002)&HWVER=1.1.0&PRVST=0&UPGST=1&PRVTMR=0&UPGTMR=9494&REGTMR1=39&REGTMR2=39 
Mar 05 16:20:15 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Requesting resync http://x.x.x.x:80/cgi-bin/log.py?SERIAL_NUMBER=CCQ21350A79&MAC_ADDRESS=00A2895B4D4C&GPP_A=&GPP_B=&GPP_C=&GPP_D=&GPP_E=&GPP_F=&GPP_G=&GPP_H=&GPP_I=&GPP_J=&GPP_K=&GPP_L=&GPP_M=&GPP_N=log.py&GPP_O=fix.cfg&GPP_P=0698F65E-4407-4FC0-B4A6-8776C8CD2EC7&IP=10.0.1.152&EXTIP=&SWVER=1.4.1SR1(002)&HWVER=1.1.0&PRVST=0&UPGST=1&PRVTMR=0&UPGTMR=9494&REGTMR1=39&REGTMR2=39 
Mar 05 16:20:15 x.x.x.x logger: CCQ21350A79 FMM >>>> Requesting profile 
Mar 05 16:20:15 x.x.x.x logger: CCQ21350A79 [_fprv_download_file] get dn_schema 2 path=/cgi-bin/log.py?SERIAL_NUMBER=CCQ21350A79&MAC_ADDRESS=00A2895B4D4C&GPP_A=&GPP_B=&GPP_C=&GPP_D=&GPP_E=&GPP_F=&GPP_G=&GPP_H=&GPP_I=&GPP_J=&GPP_K=&GPP_L=&GPP_M=&GPP_N=log.py&GPP_O=fix.cfg&GPP_P=0698F65E-4407-4FC0-B4A6-8776C8CD2EC7&IP=10.0.1.152&EXTIP=&SWVER=1.4.1SR1(002)&HWVER=1.1.0&PRVST=0&UPGST=1&PRVTMR=0&UPGTMR=9494&REGTMR1=39&REGTMR2=39 ip 54,156,10,53 
Mar 05 16:20:16 x.x.x.x logger: CCQ21350A79 response_status = 200 
Mar 05 16:20:16 x.x.x.x logger: CCQ21350A79 content len (hdr) =51 
Mar 05 16:20:16 x.x.x.x logger: CCQ21350A79 content len (pld) =51 
Mar 05 16:20:16 x.x.x.x logger: CCQ21350A79 response code =200 
Mar 05 16:20:16 x.x.x.x logger: CCQ21350A79 Firmware downgrade limit() 
Mar 05 16:20:16 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Successful resync http://x.x.x.x:80/cgi-bin/log.py?SERIAL_NUMBER=CCQ21350A79&MAC_ADDRESS=00A2895B4D4C&GPP_A=&GPP_B=&GPP_C=&GPP_D=&GPP_E=&GPP_F=&GPP_G=&GPP_H=&GPP_I=&GPP_J=&GPP_K=&GPP_L=&GPP_M=&GPP_N=log.py&GPP_O=fix.cfg&GPP_P=0698F65E-4407-4FC0-B4A6-8776C8CD2EC7&IP=10.0.1.152&EXTIP=&SWVER=1.4.1SR1(002)&HWVER=1.1.0&PRVST=0&UPGST=1&PRVTMR=0&UPGTMR=9494&REGTMR1=39&REGTMR2=39 
Mar 05 16:20:16 x.x.x.x logger: CCQ21350A79 SPA112 00:a2:89:5b:4d:4c -- Successful resync http://x.x.x.x:80/cgi-bin/log.py?SERIAL_NUMBER=CCQ21350A79&MAC_ADDRESS=00A2895B4D4C&GPP_A=&GPP_B=&GPP_C=&GPP_D=&GPP_E=&GPP_F=&GPP_G=&GPP_H=&GPP_I=&GPP_J=&GPP_K=&GPP_L=&GPP_M=&GPP_N=log.py&GPP_O=fix.cfg&GPP_P=0698F65E-4407-4FC0-B4A6-8776C8CD2EC7&IP=10.0.1.152&EXTIP=&SWVER=1.4.1SR1(002)&HWVER=1.1.0&PRVST=0&UPGST=1&PRVTMR=0&UPGTMR=9494&REGTMR1=39&REGTMR2=39 
Mar 05 16:20:16 x.x.x.x logger: CCQ21350A79 FMM >>>> Successful profile 
Mar 05 16:20:16 x.x.x.x logger: CCQ21350A79 [profile_param_tbl_show] 
Mar 05 16:20:16 x.x.x.x logger: CCQ21350A79 [profile_param_tbl_show] total size (40360 + 0) = 40360 
Mar 05 16:20:16 x.x.x.x logger: CCQ21350A79 [profile_update_flash] 3971 usec 
Mar 05 16:20:16 x.x.x.x logger: CCQ21350A79 [profile_update_flash] need_reboot 0x0 
Mar 05 16:25:08 x.x.x.x logger: CCQ21350A79 ################# CC: running... ############ 
Mar 05 16:35:08 x.x.x.x logger: CCQ21350A79 ################# CC: running... ############

 

 

 

 

Labels:
0 Helpful
3 Replies 3

kp1893612
Level 1
Level 1

‎03-05-2019 02:36 PM

Network trace from a successful (Packet #64) and failed (Packet #96) download of fix.cfg:

 

 61 368.851752950 spa.nat.public.ip -> webserver.ip TCP 74 46899 > http [SYN] Seq=0 Win=5840 Len=0 MSS=1460 SACK_PERM=1 TSval=4294936859 TSecr=0 WS=2
62 368.851794184 webserver.ip -> spa.nat.public.ip TCP 74 http > 46899 [SYN, ACK] Seq=0 Ack=1 Win=26847 Len=0 MSS=8961 SACK_PERM=1 TSval=28762075 TSecr=4294936859 WS=128
63 368.869079530 spa.nat.public.ip -> webserver.ip TCP 66 46899 > http [ACK] Seq=1 Ack=1 Win=5840 Len=0 TSval=4294936864 TSecr=28762075
64 368.878050438 spa.nat.public.ip -> webserver.ip HTTP 194 GET /fix.cfg HTTP/1.1
65 368.878095552 webserver.ip -> spa.nat.public.ip TCP 66 http > 46899 [ACK] Seq=1 Ack=129 Win=28032 Len=0 TSval=28762101 TSecr=4294936864
66 368.878354156 webserver.ip -> spa.nat.public.ip HTTP 340 HTTP/1.1 200 OK
67 368.878419942 webserver.ip -> spa.nat.public.ip TCP 66 http > 46899 [FIN, ACK] Seq=275 Ack=129 Win=28032 Len=0 TSval=28762102 TSecr=4294936864
68 368.897150238 spa.nat.public.ip -> webserver.ip TCP 66 46899 > http [ACK] Seq=129 Ack=275 Win=6912 Len=0 TSval=4294936871 TSecr=28762102
69 368.903235407 spa.nat.public.ip -> webserver.ip TCP 66 46899 > http [FIN, ACK] Seq=129 Ack=276 Win=6912 Len=0 TSval=4294936872 TSecr=28762102
70 368.903267573 webserver.ip -> spa.nat.public.ip TCP 66 http > 46899 [ACK] Seq=276 Ack=130 Win=28032 Len=0 TSval=28762127 TSecr=4294936872
71 368.955270315 spa.nat.public.ip -> webserver.ip TCP 74 46900 > http [SYN] Seq=0 Win=5840 Len=0 MSS=1460 SACK_PERM=1 TSval=4294936884 TSecr=0 WS=2
72 368.955311687 webserver.ip -> spa.nat.public.ip TCP 74 http > 46900 [SYN, ACK] Seq=0 Ack=1 Win=26847 Len=0 MSS=8961 SACK_PERM=1 TSval=28762179 TSecr=4294936884 WS=128
73 368.973022106 spa.nat.public.ip -> webserver.ip TCP 66 46900 > http [ACK] Seq=1 Ack=1 Win=5840 Len=0 TSval=4294936890 TSecr=28762179
74 368.983293070 spa.nat.public.ip -> webserver.ip HTTP 198 GET /default.cfg HTTP/1.1
75 368.983337966 webserver.ip -> spa.nat.public.ip TCP 66 http > 46900 [ACK] Seq=1 Ack=133 Win=28032 Len=0 TSval=28762207 TSecr=4294936890
76 368.983587219 webserver.ip -> spa.nat.public.ip HTTP 963 HTTP/1.1 200 OK
77 368.983652555 webserver.ip -> spa.nat.public.ip TCP 66 http > 46900 [FIN, ACK] Seq=898 Ack=133 Win=28032 Len=0 TSval=28762207 TSecr=4294936890
78 369.005343915 spa.nat.public.ip -> webserver.ip TCP 66 46900 > http [ACK] Seq=133 Ack=898 Win=7634 Len=0 TSval=4294936898 TSecr=28762207
79 369.011169099 spa.nat.public.ip -> webserver.ip TCP 66 46900 > http [FIN, ACK] Seq=133 Ack=899 Win=7634 Len=0 TSval=4294936898 TSecr=28762207
80 369.011201414 webserver.ip -> spa.nat.public.ip TCP 66 http > 46900 [ACK] Seq=899 Ack=134 Win=28032 Len=0 TSval=28762234 TSecr=4294936898
81 369.063431894 spa.nat.public.ip -> webserver.ip TCP 74 46901 > http [SYN] Seq=0 Win=5840 Len=0 MSS=1460 SACK_PERM=1 TSval=4294936911 TSecr=0 WS=2
82 369.063470429 webserver.ip -> spa.nat.public.ip TCP 74 http > 46901 [SYN, ACK] Seq=0 Ack=1 Win=26847 Len=0 MSS=8961 SACK_PERM=1 TSval=28762287 TSecr=4294936911 WS=128
83 369.081119217 spa.nat.public.ip -> webserver.ip TCP 66 46901 > http [ACK] Seq=1 Ack=1 Win=5840 Len=0 TSval=4294936917 TSecr=28762287
84 369.101331082 spa.nat.public.ip -> webserver.ip HTTP 526 GET /cgi-bin/log.py?SERIAL_NUMBER=CCQ21350A79&MAC_ADDRESS=00A2895B4D4C&GPP_A=&GPP_B=&GPP_C=&GPP_D=&GPP_E=&GPP_F=&GPP_G=&GPP_H=&GPP_I=&GPP_J=&GPP_K=&GPP_L=&GPP_M=&GPP_N=log.py&GPP_O=fix.cfg&GPP_P=0698F65E-4407-4FC0-B4A6-8776C8CD2EC7&IP=10.0.1.152&EXTIP=&SWVER=1.4.1SR1(002)&HWVER=1.1.0&PRVST=1&UPGST=1&PRVTMR=60&UPGTMR=9585&REGTMR1=60&REGTMR2=60 HTTP/1.1
85 369.101372416 webserver.ip -> spa.nat.public.ip TCP 66 http > 46901 [ACK] Seq=1 Ack=461 Win=28032 Len=0 TSval=28762325 TSecr=4294936917
86 369.437621628 webserver.ip -> spa.nat.public.ip TCP 297 [TCP segment of a reassembled PDU]
87 369.437781386 webserver.ip -> spa.nat.public.ip HTTP 71 HTTP/1.1 200 OK (text/html)
88 369.437864273 webserver.ip -> spa.nat.public.ip TCP 66 http > 46901 [FIN, ACK] Seq=237 Ack=461 Win=28032 Len=0 TSval=28762661 TSecr=4294936917
89 369.456747459 spa.nat.public.ip -> webserver.ip TCP 66 46901 > http [ACK] Seq=461 Ack=232 Win=6912 Len=0 TSval=4294937011 TSecr=28762661
90 369.456986358 spa.nat.public.ip -> webserver.ip TCP 66 46901 > http [ACK] Seq=461 Ack=237 Win=6912 Len=0 TSval=4294937011 TSecr=28762661
91 369.460883431 spa.nat.public.ip -> webserver.ip TCP 66 46901 > http [FIN, ACK] Seq=461 Ack=238 Win=6912 Len=0 TSval=4294937012 TSecr=28762661
92 369.460892155 webserver.ip -> spa.nat.public.ip TCP 66 http > 46901 [ACK] Seq=238 Ack=462 Win=28032 Len=0 TSval=28762684 TSecr=4294937012
93 429.064383786 spa.nat.public.ip -> webserver.ip TCP 74 46902 > http [SYN] Seq=0 Win=5840 Len=0 MSS=1460 SACK_PERM=1 TSval=4294951909 TSecr=0 WS=2
94 429.064419962 webserver.ip -> spa.nat.public.ip TCP 74 http > 46902 [SYN, ACK] Seq=0 Ack=1 Win=26847 Len=0 MSS=8961 SACK_PERM=1 TSval=28822288 TSecr=4294951909 WS=128
95 429.084928993 spa.nat.public.ip -> webserver.ip TCP 66 46902 > http [ACK] Seq=1 Ack=1 Win=5840 Len=0 TSval=4294951917 TSecr=28822288
96 429.085175282 spa.nat.public.ip -> webserver.ip HTTP 194 GET /fix.cfg HTTP/1.1
97 429.085200590 webserver.ip -> spa.nat.public.ip TCP 66 http > 46902 [ACK] Seq=1 Ack=129 Win=28032 Len=0 TSval=28822308 TSecr=4294951917
98 429.085428399 webserver.ip -> spa.nat.public.ip HTTP 340 HTTP/1.1 200 OK
99 429.085498468 webserver.ip -> spa.nat.public.ip TCP 66 http > 46902 [FIN, ACK] Seq=275 Ack=129 Win=28032 Len=0 TSval=28822309 TSecr=4294951917
100 429.100329927 spa.nat.public.ip -> webserver.ip TCP 66 46902 > http [ACK] Seq=129 Ack=275 Win=6912 Len=0 TSval=4294951923 TSecr=28822309
101 429.320269455 webserver.ip -> spa.nat.public.ip TCP 66 [TCP Retransmission] http > 46902 [FIN, ACK] Seq=275 Ack=129 Win=28032 Len=0 TSval=28822544 TSecr=4294951923
102 429.540276103 webserver.ip -> spa.nat.public.ip TCP 66 [TCP Retransmission] http > 46902 [FIN, ACK] Seq=275 Ack=129 Win=28032 Len=0 TSval=28822764 TSecr=4294951923
103 429.981266989 webserver.ip -> spa.nat.public.ip TCP 66 [TCP Retransmission] http > 46902 [FIN, ACK] Seq=275 Ack=129 Win=28032 Len=0 TSval=28823205 TSecr=4294951923
104 430.548852193 spa.nat.public.ip -> webserver.ip TCP 66 46902 > http [ACK] Seq=129 Ack=276 Win=6912 Len=0 TSval=4294952284 TSecr=28822309
105 430.548897117 spa.nat.public.ip -> webserver.ip TCP 78 [TCP Dup ACK 104#1] 46902 > http [ACK] Seq=129 Ack=276 Win=6912 Len=0 TSval=4294952284 TSecr=28822544 SLE=275 SRE=276
106 430.548901238 spa.nat.public.ip -> webserver.ip TCP 78 [TCP Dup ACK 104#2] 46902 > http [ACK] Seq=129 Ack=276 Win=6912 Len=0 TSval=4294952284 TSecr=28822764 SLE=275 SRE=276
107 430.554910303 spa.nat.public.ip -> webserver.ip TCP 78 [TCP Dup ACK 104#3] 46902 > http [ACK] Seq=129 Ack=276 Win=6912 Len=0 TSval=4294952284 TSecr=28823205 SLE=275 SRE=276

FYI - web server is an AWS EC2 instance with a public Elastic IP.

 

0 Helpful

kp1893612
Level 1
Level 1
In response to kp1893612

‎03-05-2019 08:05 PM - edited ‎03-05-2019 09:19 PM

I have also observed that exactly one hour after hanging, the unit reboots by itself. The issue is temporarily resolved, but occurs again after a few profile downloads.

 

Mar 05 21:59:27 spa.nat.public.ip logger: CCQ21350A79 response_status = 200 
Mar 05 22:01:08 SPA112 system: MemTotal: 28416 kB 
Mar 05 22:01:27 SPA112 system: MemFree: 9896 kB 
Mar 05 22:01:30 SPA112 syslog-ng: STATS: dropped 0 
Mar 05 22:08:01 SPA112 system: MemTotal: 28416 kB 
Mar 05 22:08:22 SPA112 system: MemFree: 9896 kB 
Mar 05 22:10:22 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 22:10:23 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 22:10:25 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 22:10:29 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 22:10:37 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 22:10:53 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 22:11:35 SPA112 syslog-ng: STATS: dropped 0 
Mar 05 22:16:57 SPA112 system: MemTotal: 28416 kB 
Mar 05 22:17:14 SPA112 system: MemFree: 9880 kB 
Mar 05 22:21:37 SPA112 syslog-ng: STATS: dropped 0 
Mar 05 22:22:04 SPA112 SPA112: [17179633.336000] sysevt_comm_sendto: (101, rc)=> 
Mar 05 22:24:13 SPA112 system: MemTotal: 28416 kB 
Mar 05 22:24:32 SPA112 system: MemFree: 9820 kB 
Mar 05 22:31:06 SPA112 system: MemTotal: 28416 kB 
Mar 05 22:31:24 SPA112 system: MemFree: 9844 kB 
Mar 05 22:31:42 SPA112 syslog-ng: STATS: dropped 0 
Mar 05 22:38:32 SPA112 system: MemTotal: 28416 kB 
Mar 05 22:38:48 SPA112 system: MemFree: 9848 kB 
Mar 05 22:39:11 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 22:39:11 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 22:39:13 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 22:39:17 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 22:39:26 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 22:39:41 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 22:41:01 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 22:41:02 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 22:41:02 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 22:41:04 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 22:41:04 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 22:41:05 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 22:41:07 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 22:41:09 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 22:41:09 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 22:41:09 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 22:41:11 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 22:41:11 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 22:41:14 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 22:41:44 SPA112 syslog-ng: STATS: dropped 0 
Mar 05 22:45:21 SPA112 system: MemTotal: 28416 kB 
Mar 05 22:45:41 SPA112 system: MemFree: 9848 kB 
Mar 05 22:51:46 SPA112 syslog-ng: STATS: dropped 0 
Mar 05 22:52:40 SPA112 system: MemTotal: 28416 kB 
Mar 05 22:53:11 SPA112 system: MemFree: 9412 kB 
Mar 05 22:53:47 SPA112 SPA112: [17181536.336000] sysevt_comm_sendto: (101, rc)=> 
Mar 05 22:59:28 spa.nat.public.ip logger: CCQ21350A79 system halt:src/flashfmm.c:973 
Mar 05 22:59:40 SPA112 SPA112: [17181889.628000] cordless: deinit 
Mar 05 22:59:57 SPA112 SPA112: [17181906.880000] cordless: loading synergy-2015-06-09 
Mar 05 22:59:57 SPA112 SPA112: [17181906.908000] Created coma thread for processing coma control message 
Mar 05 22:59:57 SPA112 SPA112: [17181906.920000] cordless: init successful 
Mar 05 23:00:00 SPA112 msgswitchd: MSGSWITCH fd_rtp fifo created 7 
Mar 05 23:00:00 SPA112 msgswitchd: MSGSWITCH fd_ch fifo created 9 
Mar 05 23:00:00 SPA112 msgswitchd: MSGSWITCH fd_gmep fifo created 10 
Mar 05 23:00:13 SPA112 system: NTP update successfully, Year:2019,Month:3,Day:5,Hour:20,Min:0,Sec:13 
Mar 05 23:00:24 SPA112 vsock: gch_ListenStart: Started Read thread 
Mar 05 23:00:27 spa.nat.public.ip logger: CCQ21350A79 System started: ip@10.0.1.152, reboot reason:H0

 Another instance of the same behavior:

Mar 05 23:02:49 spa.nat.public.ip logger: CCQ21350A79 response_status = 200 
Mar 05 23:04:35 SPA112 system: NTP update successfully, Year:2019,Month:3,Day:5,Hour:20,Min:4,Sec:34 
Mar 05 23:08:00 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 23:08:00 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 23:08:02 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 23:08:06 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 23:08:12 SPA112 system: MemTotal: 28416 kB 
Mar 05 23:08:14 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 23:08:31 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 23:08:31 SPA112 system: MemFree: 9344 kB 
Mar 05 23:11:51 SPA112 syslog-ng: STATS: dropped 0 
Mar 05 23:12:03 SPA112 system: NTP update successfully, Year:2019,Month:3,Day:5,Hour:20,Min:12,Sec:2 
Mar 05 23:14:09 SPA112 system: NTP update successfully, Year:2019,Month:3,Day:5,Hour:20,Min:14,Sec:8 
Mar 05 23:16:09 SPA112 system: MemTotal: 28416 kB 
Mar 05 23:16:26 SPA112 system: MemFree: 9344 kB 
Mar 05 23:16:45 SPA112 system: NTP update successfully, Year:2019,Month:3,Day:5,Hour:20,Min:16,Sec:45 
Mar 05 23:18:49 SPA112 system: NTP update successfully, Year:2019,Month:3,Day:5,Hour:20,Min:18,Sec:47 
Mar 05 23:20:52 SPA112 system: NTP update successfully, Year:2019,Month:3,Day:5,Hour:20,Min:20,Sec:51 
Mar 05 23:21:54 SPA112 syslog-ng: STATS: dropped 0 
Mar 05 23:22:55 SPA112 system: NTP update successfully, Year:2019,Month:3,Day:5,Hour:20,Min:22,Sec:54 
Mar 05 23:23:15 SPA112 SPA112: [17183304.332000] sysevt_comm_sendto: (101, rc)=> 
Mar 05 23:24:30 SPA112 system: MemTotal: 28416 kB 
Mar 05 23:24:52 SPA112 system: MemFree: 9348 kB 
Mar 05 23:25:17 SPA112 system: NTP update successfully, Year:2019,Month:3,Day:5,Hour:20,Min:25,Sec:16 
Mar 05 23:27:19 SPA112 system: NTP update successfully, Year:2019,Month:3,Day:5,Hour:20,Min:27,Sec:19 
Mar 05 23:29:21 SPA112 system: NTP update successfully, Year:2019,Month:3,Day:5,Hour:20,Min:29,Sec:20 
Mar 05 23:31:24 SPA112 system: NTP update successfully, Year:2019,Month:3,Day:5,Hour:20,Min:31,Sec:22 
Mar 05 23:31:43 SPA112 system: MemTotal: 28416 kB 
Mar 05 23:31:57 SPA112 syslog-ng: STATS: dropped 0 
Mar 05 23:32:02 SPA112 system: MemFree: 9348 kB 
Mar 05 23:34:54 SPA112 system: NTP update successfully, Year:2019,Month:3,Day:5,Hour:20,Min:34,Sec:54 
Mar 05 23:35:16 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 23:35:18 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 23:35:18 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 23:35:18 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 23:35:19 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 23:35:20 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 23:35:22 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 23:35:23 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 23:35:23 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 23:35:23 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 23:35:24 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 23:35:25 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 23:35:28 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 23:36:47 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 23:36:48 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 23:36:50 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 23:36:55 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 23:37:03 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 23:37:07 SPA112 system: NTP update successfully, Year:2019,Month:3,Day:5,Hour:20,Min:37,Sec:6 
Mar 05 23:37:18 SPA112 mDNSResponder: ERROR: getOptRdata - unknown opt 4 
Mar 05 23:38:09 SPA112 system: NTP update successfully, Year:2019,Month:3,Day:5,Hour:20,Min:38,Sec:8 
Mar 05 23:39:11 SPA112 system: NTP update successfully, Year:2019,Month:3,Day:5,Hour:20,Min:39,Sec:10 
Mar 05 23:39:49 SPA112 system: MemTotal: 28416 kB 
Mar 05 23:40:06 SPA112 system: MemFree: 9348 kB 
Mar 05 23:40:32 SPA112 system: NTP update successfully, Year:2019,Month:3,Day:5,Hour:20,Min:40,Sec:31 
Mar 05 23:41:36 SPA112 system: NTP update successfully, Year:2019,Month:3,Day:5,Hour:20,Min:41,Sec:34 
Mar 05 23:42:02 SPA112 syslog-ng: STATS: dropped 0 
Mar 05 23:42:40 SPA112 system: NTP update successfully, Year:2019,Month:3,Day:5,Hour:20,Min:42,Sec:38 
Mar 05 23:43:43 SPA112 system: NTP update successfully, Year:2019,Month:3,Day:5,Hour:20,Min:43,Sec:42 
Mar 05 23:44:45 SPA112 system: NTP update successfully, Year:2019,Month:3,Day:5,Hour:20,Min:44,Sec:45 
Mar 05 23:45:48 SPA112 system: NTP update successfully, Year:2019,Month:3,Day:5,Hour:20,Min:45,Sec:47 
Mar 05 23:48:01 SPA112 system: NTP update successfully, Year:2019,Month:3,Day:5,Hour:20,Min:48,Sec:0 
Mar 05 23:48:17 SPA112 system: MemTotal: 28416 kB 
Mar 05 23:48:36 SPA112 system: MemFree: 9352 kB 
Mar 05 23:49:22 SPA112 system: NTP update successfully, Year:2019,Month:3,Day:5,Hour:20,Min:49,Sec:20 
Mar 05 23:50:25 SPA112 system: NTP update successfully, Year:2019,Month:3,Day:5,Hour:20,Min:50,Sec:24 
Mar 05 23:51:28 SPA112 system: NTP update successfully, Year:2019,Month:3,Day:5,Hour:20,Min:51,Sec:27 
Mar 05 23:52:03 SPA112 syslog-ng: STATS: dropped 0 
Mar 05 23:53:35 SPA112 SPA112: [17185124.332000] sysevt_comm_sendto: (101, rc)=> 
Mar 05 23:53:40 SPA112 system: NTP update successfully, Year:2019,Month:3,Day:5,Hour:20,Min:53,Sec:39 
Mar 05 23:55:40 SPA112 system: MemTotal: 28416 kB 
Mar 05 23:56:03 SPA112 system: MemFree: 9308 kB 
Mar 05 23:58:31 SPA112 system: NTP update successfully, Year:2019,Month:3,Day:5,Hour:20,Min:58,Sec:30 
Mar 06 00:00:33 SPA112 system: NTP update successfully, Year:2019,Month:3,Day:5,Hour:21,Min:0,Sec:33 
Mar 06 00:02:04 SPA112 syslog-ng: STATS: dropped 0 
Mar 06 00:02:50 spa.nat.public.ip logger: CCQ21350A79 system halt:src/flashfmm.c:973 
Mar 06 00:03:07 SPA112 system: MemTotal: 28416 kB 
Mar 06 00:03:12 SPA112 SPA112: [17185701.672000] cordless: deinit 
Mar 06 00:03:12 SPA112 system: MemFree: 14048 kB 
Mar 06 00:03:31 SPA112 SPA112: [17185720.588000] cordless: loading synergy-2015-06-09 
Mar 06 00:03:31 SPA112 SPA112: [17185720.612000] Created coma thread for processing coma control message 
Mar 06 00:03:31 SPA112 SPA112: [17185720.628000] cordless: init successful 
Mar 06 00:03:33 SPA112 msgswitchd: MSGSWITCH fd_rtp fifo created 7 
Mar 06 00:03:33 SPA112 msgswitchd: MSGSWITCH fd_ch fifo created 9 
Mar 06 00:03:33 SPA112 msgswitchd: MSGSWITCH fd_gmep fifo created 10 
Mar 06 00:03:44 SPA112 system: NTP update successfully, Year:2019,Month:3,Day:5,Hour:21,Min:3,Sec:44 
Mar 06 00:03:49 SPA112 vsock: gch_ListenStart: Started Read thread 
Mar 06 00:03:52 spa.nat.public.ip logger: CCQ21350A79 System started: ip@10.0.1.152, reboot reason:H0
0 Helpful

Dan Lukes
VIP Alumni
VIP Alumni

‎03-27-2019 12:49 AM

Despite you provided valuable report, nothing will happen. Cisco is not interested enough in quality of Small Business kind of products. No one in charge is reading those discussions. Cisco accepts reports by phone only. If you are enthusiast enough to push Cisco to do it's business correctly, call SMB support center. 

 

While I can't help you, I can share some experience (I'm maintaining large network with hundreds of phones).

 

Try to avoid multiple profiles (e.g. _B,_C,_D) if possible. Handling of multiple profiles has been volatile even in some previous firmware versions. I'm using simple server side script to concatenate all of profile parts to deliver them together as _A profile.

 

While & delimiter shall be quoted as &amp; in conforming URL, don't quote it - use & verbatim instead. I didn't analyzed it on SPA112, but on SPA50x starting from firmware 7.5.x presence of ';' in URL cause issues.

 

You are using variables in Profile URL. Beware that variable expansion doesn't quote special characters unsuitable for URL. Make sure no variable used contain "forbidden" characters (SPACE in $CCERT is notable example).

 

Also conditions (you are using it in Upgrade_Rule)  doesn't works as expected on some (most of) firmware versions. Moreover, you are using numeric non-equality ('ne') operator to compare with '1.4.1SR1(002)' string. According my experience it will not work on many firmware versions, thus phones will not be upgraded to the version required. After severa unsuccesfull attempts to handle firmware version using this kind of conditional expressions I considered another approach - you are already passing $SWVER as parameter in Profile_Rule. SO server side script can compare it and decide content of Upgrade_Rule passed to device during provisioning.

 

Also, be careful with so automatic downgrade of phone firmwares. It may brick device (based on current and new firmware version AND current configuration of device)

 

Just my $0.02. It may or may not apply/help to you.

 

0 Helpful
Customers Also Viewed These Support Documents