Re: Weird DHCP issue with CP7841 phones

jsgilesbv2012 · ‎06-12-2018

Hello All,

Hoping to get some guidance and some help with a weird DHCP issue I'm facing with only my 7841 SIP phones.
layout:

2 UCM servers
2 Unity servers
2 UCCX servers

1 IM&P sever

one Virtual machine on the same network for DHCP

Phone system has a majority(100's) of 7942 phones, and now about 25-30 7841 phones

7942 phones are using SCCP and have no problems at all

7841 phones are using SIP and I began to see this problem start about 1 month ago.

I had been able to provision these 7841 fine up until this point.

Here is the issue:

When I provision the phone for the user, the phone gets its correct network information from the DHCP server, however, the phone will not complete the registration process until I manually disable DHCP on the phone ( keeping the network settings obtained from DHCP). thats pretty much the issue, nothing else has really changed anywhere else that I can think of. I recently upgraded the entire system from 10.x to 11.x and still have the same problem before and after. The reason for upgrading was for a different company initiative.

Here are some logs from the initial startup:

3 - Cisco Systems - # RELEASE Model=78xx Version=12-0-1-11
[ ] Tue Jun 12 14:40:09 2018
=============================================================[V05][HW ver: 33
][3]
1697 INF Jun 12 14:40:09.058110 syslogd forced rotation
1698 NOT Jun 12 14:40:10.118449 (1091:1091) sarch: -Archiving syslogs to /logsave/main max=999 
1699 NOT Jun 12 14:40:11.308591 (1137:1137) sarch: -dir size /logsave/main is 8183808 
1700 NOT Jun 12 14:40:11.385045 (1139:1139) sarch: -echo archiving /tmp/20180612_144010.tar.gz 
1701 NOT Jun 12 14:40:18.389623 (429:457) CDP-cdpRcvPkt(): deviceId is IDF2_VSA
1702 WRN Jun 12 14:40:22.499893 (429:457) CDP-lldpProcessOrgSpecTLV() Invalid PD request value 44
1703 NOT Jun 12 14:40:26.776835 (429:457) CDP-cdpRcvPkt(): deviceId is IDF2_VSA
1704 NOT Jun 12 14:40:29.567739 (718:906) DHCP-readThrd(): tVals: 0   dinfo->state != BOUND 
1705 NOT Jun 12 14:40:30.098947 (718:906) DHCP-readThrd(): tVals: 0   dinfo->state != BOUND 
1706 WRN Jun 12 14:40:31.856554 (718:906) DHCP-dhcpReadThrd(): response not received, try again... 
1707 NOT Jun 12 14:40:31.856737 (718:906) DHCP-dhcpTmrExp(): exceeded max retries:  state: REQUESTING      mode: LISTEN_RAW 
1708 NOT Jun 12 14:40:31.859545 (718:906) DHCP-dhcpSendReq(): Sending Discover... 
1709 WRN Jun 12 14:40:35.861498 (718:906) DHCP-dhcpReadThrd(): response not received, try again... 
1710 NOT Jun 12 14:40:35.865435 (718:724) DHCP-dhcpParseInfo(): dinfo->ntp_addr[0] = 0x0; dinfo->ntp_addr[1] = 0x0
1711 NOT Jun 12 14:40:35.865557 (718:724) DHCP-dhcpParseInfo(): vendor_opt43
1712 NOT Jun 12 14:40:35.865649 (718:724) DHCP-dhcpParseInfo(): dinfo->vendor_opt43 = 
1713 NOT Jun 12 14:40:35.865740 (718:724) DHCP-dhcpParseInfo(): dinfo->vendor_opt125 = 
1714 NOT Jun 12 14:40:35.865923 (718:724) DHCP-dhcpRcvPkt(): Sending Request... 
1715 WRN Jun 12 14:40:39.866351 (718:906) DHCP-dhcpReadThrd(): response not received, try again... 
1716 WRN Jun 12 14:40:47.869037 (718:906) DHCP-dhcpReadThrd(): response not received, try again... 
1717 NOT Jun 12 14:40:48.410041 (429:457) CDP-cdpRcvPkt(): deviceId is IDF2_VSA
1718 WRN Jun 12 14:40:52.542713 (429:457) CDP-lldpProcessOrgSpecTLV() Invalid PD request value 44
1719 NOT Jun 12 14:41:00.249778 (588:909) JAVA-NIOGetEvent: hard key event read
1720 INF Jun 12 14:41:00.249961 (588:909) JAVA-[[MESSAGE_1.0]]: [NativeIO] --> 4.1(press) --> [JAVA] :
1721 NOT Jun 12 14:41:00.250389 (588:909) JAVA-NativeUserInput|cip.userio.InputManager$NativeEventThread:? - Forwarding native input event
1722 INF Jun 12 14:41:00.250907 (588:909) JAVA-NativeUserInput|cip.userio.InputManager:? - Received GOF4: 1
1723 INF Jun 12 14:41:00.256950 (588:930) JAVA-PushThread|cip.push.PushThread:execute - Sleep for 100ms previous= current=BuiltinApp:Applications i=0 total=1
1724 NOT Jun 12 14:41:00.393407 (588:909) JAVA-NIOGetEvent: hard key event read
1725 INF Jun 12 14:41:00.393590 (588:909) JAVA-[[MESSAGE_1.0]]: [NativeIO] --> 4.1(release) --> [JAVA] :
1726 NOT Jun 12 14:41:00.393987 (588:909) JAVA-NativeUserInput|cip.userio.InputManager$NativeEventThread:? - Forwarding native input event
1727 INF Jun 12 14:41:00.394506 (588:909) JAVA-NativeUserInput|cip.userio.InputManager:? - Received GOF4: 1
1728 NOT Jun 12 14:41:00.399053 (370:383) PWRMAN-setMode(): NORMAL 
1729 NOT Jun 12 14:41:00.399389 (588:739) JAVA-Calling handlePowerManEvent
1730 NOT Jun 12 14:41:00.399725 (588:739) JAVA-Calling handlePowerManEvent
1731 DEB Jun 12 14:41:00.403418 kernel: [  189.577292] Set LCD backlight 1
1732 NOT Jun 12 14:41:00.478345 (588:935) JAVA-appmenu MQThread|cip.g3.menuapp.MenuApp:? - Service url used https://BVCUCM1:8443/ccmcip/getservicesmenu.jsp
1733 NOT Jun 12 14:41:00.479139 (588:935) JAVA-appmenu MQThread|cip.g3.menuapp.MenuApp:? - Service url used https://BVCUCM1:8443/ccmcip/getservicesmenu.jsp
1734 WRN Jun 12 14:41:03.875385 (718:906) DHCP-dhcpReadThrd(): response not received, try again... 
1735 NOT Jun 12 14:41:04.145734 (595:610) DHCP6: -SIGALRM received
1736 NOT Jun 12 14:41:04.165511 (595:623) DHCP6: -client6_timo(): ev 0xb87ed548 ev->state = 1 ev->timeouts = 7
1737 NOT Jun 12 14:41:04.165756 (595:623) DHCP6: -set client ID (len 10)
1738 NOT Jun 12 14:41:04.165847 (595:623) DHCP6: -set vendor class (len 20)
1739 NOT Jun 12 14:41:04.165939 (595:623) DHCP6: -set IA address
1740 NOT Jun 12 14:41:04.166030 (595:623) DHCP6: -set identity association
1741 NOT Jun 12 14:41:04.166091 (595:623) DHCP6: -set elapsed time (len 2)
1742 NOT Jun 12 14:41:04.166152 (595:623) DHCP6: -set option request (len 6)
1743 NOT Jun 12 14:41:04.167526 (595:623) DHCP6: -Send solicit
1744 NOT Jun 12 14:41:04.167709 (595:623) DHCP6: -client6_timo(): send out request pkt at 2
1745 NOT Jun 12 14:41:04.167862 (595:623) DHCP6: -reset a timer state=SOLICIT, timeo=7, retrans=115788
1746 NOT Jun 12 14:41:15.594994 (588:909) JAVA-NIOGetEvent: hard key event read
1747 INF Jun 12 14:41:15.595177 (588:909) JAVA-[[MESSAGE_1.0]]: [NativeIO] --> 2.2(press) --> [JAVA] :
1748 NOT Jun 12 14:41:15.595544 (588:909) JAVA-NativeUserInput|cip.userio.InputManager$NativeEventThread:? - Forwarding native input event
1749 INF Jun 12 14:41:15.605554 (588:909) JAVA-NativeUserInput|cip.userio.InputManager:? - Received Navigation: 2
1750 NOT Jun 12 14:41:15.743415 (588:909) JAVA-NIOGetEvent: hard key event read
1751 INF Jun 12 14:41:15.743567 (588:909) JAVA-[[MESSAGE_1.0]]: [NativeIO] --> 2.2(release) --> [JAVA] :
1752 NOT Jun 12 14:41:15.744483 (588:909) JAVA-NativeUserInput|cip.userio.InputManager$NativeEventThread:? - Forwarding native input event
1753 INF Jun 12 14:41:15.745093 (588:909) JAVA-NativeUserInput|cip.userio.InputManager:? - Received Navigation: 2
1754 NOT Jun 12 14:41:15.750434 (370:383) PWRMAN-setMode(): NORMAL 
1755 NOT Jun 12 14:41:15.750801 (588:739) JAVA-Calling handlePowerManEvent
1756 NOT Jun 12 14:41:15.751014 (588:739) JAVA-Calling handlePowerManEvent
1757 DEB Jun 12 14:41:15.753364 kernel: [  204.928856] Set LCD backlight 1
1758 NOT Jun 12 14:41:15.843399 (588:909) JAVA-NIOGetEvent: hard key event read
1759 INF Jun 12 14:41:15.843583 (588:909) JAVA-[[MESSAGE_1.0]]: [NativeIO] --> 2.2(press) --> [JAVA] :
1760 NOT Jun 12 14:41:15.844010 (588:909) JAVA-NativeUserInput|cip.userio.InputManager$NativeEventThread:? - Forwarding native input event
1761 INF Jun 12 14:41:15.844529 (588:909) JAVA-NativeUserInput|cip.userio.InputManager:? - Received Navigation: 2
1762 NOT Jun 12 14:41:15.993407 (588:909) JAVA-NIOGetEvent: hard key event read
1763 INF Jun 12 14:41:15.993590 (588:909) JAVA-[[MESSAGE_1.0]]: [NativeIO] --> 2.2(release) --> [JAVA] :
1764 NOT Jun 12 14:41:15.993987 (588:909) JAVA-NativeUserInput|cip.userio.InputManager$NativeEventThread:? - Forwarding native input event
1765 INF Jun 12 14:41:15.994475 (588:909) JAVA-NativeUserInput|cip.userio.InputManager:? - Received Navigation: 2
1766 DEB Jun 12 14:41:16.014008 kernel: [  205.191637] Set LCD backlight 1
1767 NOT Jun 12 14:41:16.014558 (370:383) PWRMAN-setMode(): NORMAL 
1768 NOT Jun 12 14:41:16.014924 (588:739) JAVA-Calling handlePowerManEvent
1769 NOT Jun 12 14:41:16.015168 (588:739) JAVA-Calling handlePowerManEvent
1770 NOT Jun 12 14:41:16.108438 (588:909) JAVA-NIOGetEvent: hard key event read
1771 INF Jun 12 14:41:16.108591 (588:909) JAVA-[[MESSAGE_1.0]]: [NativeIO] --> 2.2(press) --> [JAVA] :
1772 NOT Jun 12 14:41:16.108988 (588:909) JAVA-NativeUserInput|cip.userio.InputManager$NativeEventThread:? - Forwarding native input event
1773 INF Jun 12 14:41:16.109537 (588:909) JAVA-NativeUserInput|cip.userio.InputManager:? - Received Navigation: 2
1774 NOT Jun 12 14:41:16.253380 (588:909) JAVA-NIOGetEvent: hard key event read
1775 INF Jun 12 14:41:16.253563 (588:909) JAVA-[[MESSAGE_1.0]]: [NativeIO] --> 2.2(release) --> [JAVA] :
1776 NOT Jun 12 14:41:16.253959 (588:909) JAVA-NativeUserInput|cip.userio.InputManager$NativeEventThread:? - Forwarding native input event
1777 INF Jun 12 14:41:16.254448 (588:909) JAVA-NativeUserInput|cip.userio.InputManager:? - Received Navigation: 2
1778 NOT Jun 12 14:41:16.261529 (370:383) PWRMAN-setMode(): NORMAL 
1779 NOT Jun 12 14:41:16.261895 (588:739) JAVA-Calling handlePowerManEvent
1780 NOT Jun 12 14:41:16.262139 (588:739) JAVA-Calling handlePowerManEvent
1781 DEB Jun 12 14:41:16.263390 kernel: [  205.439737] Set LCD backlight 1
1782 NOT Jun 12 14:41:18.000427 (588:909) JAVA-NIOGetEvent: hard key event read
1783 INF Jun 12 14:41:18.000610 (588:909) JAVA-[[MESSAGE_1.0]]: [NativeIO] --> 2.2(press) --> [JAVA] :
1784 NOT Jun 12 14:41:18.001007 (588:909) JAVA-NativeUserInput|cip.userio.InputManager$NativeEventThread:? - Forwarding native input event
1785 INF Jun 12 14:41:18.001525 (588:909) JAVA-NativeUserInput|cip.userio.InputManager:? - Received Navigation: 2
1786 NOT Jun 12 14:41:18.143384 (588:909) JAVA-NIOGetEvent: hard key event read
1787 INF Jun 12 14:41:18.143567 (588:909) JAVA-[[MESSAGE_1.0]]: [NativeIO] --> 2.2(release) --> [JAVA] :
1788 NOT Jun 12 14:41:18.143995 (588:909) JAVA-NativeUserInput|cip.userio.InputManager$NativeEventThread:? - Forwarding native input event
1789 INF Jun 12 14:41:18.144483 (588:909) JAVA-NativeUserInput|cip.userio.InputManager:? - Received Navigation: 2
1790 NOT Jun 12 14:41:18.150404 (370:383) PWRMAN-setMode(): NORMAL 
1791 NOT Jun 12 14:41:18.150770 (588:739) JAVA-Calling handlePowerManEvent
1792 NOT Jun 12 14:41:18.150984 (588:739) JAVA-Calling handlePowerManEvent
1793 DEB Jun 12 14:41:18.153395 kernel: [  207.328826] Set LCD backlight 1
1794 NOT Jun 12 14:41:18.306027 (588:909) JAVA-NIOGetEvent: hard key event read
1795 INF Jun 12 14:41:18.306455 (588:909) JAVA-[[MESSAGE_1.0]]: [NativeIO] --> 2.9(press) --> [JAVA] :
1796 NOT Jun 12 14:41:18.306912 (588:909) JAVA-NativeUserInput|cip.userio.InputManager$NativeEventThread:? - Forwarding native input event
1797 INF Jun 12 14:41:18.307431 (588:909) JAVA-NativeUserInput|cip.userio.InputManager:? - Received Navigation: 9
1798 INF Jun 12 14:41:18.322295 (588:930) JAVA-PushThread|cip.push.PushThread:execute - Sleep for 100ms previous= current=BuildinApp:Settings i=0 total=1
1799 NOT Jun 12 14:41:18.449351 (429:457) CDP-cdpRcvPkt(): deviceId is IDF2_VSA
1800 NOT Jun 12 14:41:18.503402 (588:909) JAVA-NIOGetEvent: hard key event read
1801 INF Jun 12 14:41:18.503586 (588:909) JAVA-[[MESSAGE_1.0]]: [NativeIO] --> 2.9(release) --> [JAVA] :
1802 NOT Jun 12 14:41:18.503982 (588:909) JAVA-NativeUserInput|cip.userio.InputManager$NativeEventThread:? - Forwarding native input event
1803 INF Jun 12 14:41:18.504501 (588:909) JAVA-NativeUserInput|cip.userio.InputManager:? - Received Navigation: 9
1804 NOT Jun 12 14:41:18.509903 (370:383) PWRMAN-setMode(): NORMAL 
1805 NOT Jun 12 14:41:18.510270 (588:739) JAVA-Calling handlePowerManEvent
1806 NOT Jun 12 14:41:18.510514 (588:739) JAVA-Calling handlePowerManEvent
1807 DEB Jun 12 14:41:18.513413 kernel: [  207.687746] Set LCD backlight 1
1808 NOT Jun 12 14:41:19.654143 (588:909) JAVA-NIOGetEvent: hard key event read
1809 INF Jun 12 14:41:19.654295 (588:909) JAVA-[[MESSAGE_1.0]]: [NativeIO] --> 2.9(press) --> [JAVA] :
1810 NOT Jun 12 14:41:19.654692 (588:909) JAVA-NativeUserInput|cip.userio.InputManager$NativeEventThread:? - Forwarding native input event
1811 INF Jun 12 14:41:19.655180 (588:909) JAVA-NativeUserInput|cip.userio.InputManager:? - Received Navigation: 9
1812 NOT Jun 12 14:41:19.853593 (588:909) JAVA-NIOGetEvent: hard key event read
1813 INF Jun 12 14:41:19.853776 (588:909) JAVA-[[MESSAGE_1.0]]: [NativeIO] --> 2.9(release) --> [JAVA] :
1814 NOT Jun 12 14:41:19.854204 (588:909) JAVA-NativeUserInput|cip.userio.InputManager$NativeEventThread:? - Forwarding native input event
1815 INF Jun 12 14:41:19.854753 (588:909) JAVA-NativeUserInput|cip.userio.InputManager:? - Received Navigation: 9
1816 NOT Jun 12 14:41:19.860949 (370:383) PWRMAN-setMode(): NORMAL 
1817 NOT Jun 12 14:41:19.861345 (588:739) JAVA-Calling handlePowerManEvent
1818 NOT Jun 12 14:41:19.861590 (588:739) JAVA-Calling handlePowerManEvent
1819 DEB Jun 12 14:41:19.863421 kernel: [  209.039371] Set LCD backlight 1
1820 NOT Jun 12 14:41:20.911765 (588:909) JAVA-NIOGetEvent: hard key event read
1821 INF Jun 12 14:41:20.911948 (588:909) JAVA-[[MESSAGE_1.0]]: [NativeIO] --> 2.9(press) --> [JAVA] :
1822 NOT Jun 12 14:41:20.913169 (588:909) JAVA-NativeUserInput|cip.userio.InputManager$NativeEventThread:? - Forwarding native input event
1823 INF Jun 12 14:41:20.913810 (588:909) JAVA-NativeUserInput|cip.userio.InputManager:? - Received Navigation: 9
1824 NOT Jun 12 14:41:21.103433 (588:909) JAVA-NIOGetEvent: hard key event read
1825 INF Jun 12 14:41:21.103586 (588:909) JAVA-[[MESSAGE_1.0]]: [NativeIO] --> 2.9(release) --> [JAVA] :
1826 NOT Jun 12 14:41:21.389439 (588:909) JAVA-NativeUserInput|cip.userio.InputManager$NativeEventThread:? - Forwarding native input event
1827 INF Jun 12 14:41:21.390843 (588:909) JAVA-NativeUserInput|cip.userio.InputManager:? - Received Navigation: 9
1828 NOT Jun 12 14:41:21.395727 (370:383) PWRMAN-setMode(): NORMAL 
1829 NOT Jun 12 14:41:21.396154 (588:739) JAVA-Calling handlePowerManEvent
1830 NOT Jun 12 14:41:21.396368 (588:739) JAVA-Calling handlePowerManEvent
1831 DEB Jun 12 14:41:21.403387 kernel: [  210.573874] Set LCD backlight 1
1832 WRN Jun 12 14:41:22.591332 (429:457) CDP-lldpProcessOrgSpecTLV() Invalid PD request value 44
1833 NOT Jun 12 14:41:24.690401 (588:909) JAVA-NIOGetEvent: hard key event read
1834 INF Jun 12 14:41:24.690553 (588:909) JAVA-[[MESSAGE_1.0]]: [NativeIO] --> 5.2(press) --> [JAVA] :
1835 NOT Jun 12 14:41:24.690950 (588:909) JAVA-NativeUserInput|cip.userio.InputManager$NativeEventThread:? - Forwarding native input event
1836 INF Jun 12 14:41:24.691805 (588:909) JAVA-NativeUserInput|cip.userio.InputManager:? - Received SOFT: 2
1837 NOT Jun 12 14:41:24.883412 (588:909) JAVA-NIOGetEvent: hard key event read
1838 INF Jun 12 14:41:24.883564 (588:909) JAVA-[[MESSAGE_1.0]]: [NativeIO] --> 5.2(release) --> [JAVA] :
1839 NOT Jun 12 14:41:24.883961 (588:909) JAVA-NativeUserInput|cip.userio.InputManager$NativeEventThread:? - Forwarding native input event
1840 INF Jun 12 14:41:24.885457 (588:909) JAVA-NativeUserInput|cip.userio.InputManager:? - Received SOFT: 2
1841 NOT Jun 12 14:41:24.890492 (370:383) PWRMAN-setMode(): NORMAL 
1842 NOT Jun 12 14:41:24.890859 (588:739) JAVA-Calling handlePowerManEvent
1843 NOT Jun 12 14:41:24.891103 (588:739) JAVA-Calling handlePowerManEvent
1844 DEB Jun 12 14:41:24.893392 kernel: [  214.068151] Set LCD backlight 1
1845 NOT Jun 12 14:41:26.790141 (429:457) CDP-cdpRcvPkt(): deviceId is IDF2_VSA
1846 NOT Jun 12 14:41:27.064184 (588:909) JAVA-NIOGetEvent: hard key event read
1847 INF Jun 12 14:41:27.064367 (588:909) JAVA-[[MESSAGE_1.0]]: [NativeIO] --> 5.2(press) --> [JAVA] :
1848 NOT Jun 12 14:41:27.064764 (588:909) JAVA-NativeUserInput|cip.userio.InputManager$NativeEventThread:? - Forwarding native input event
1849 INF Jun 12 14:41:27.065588 (588:909) JAVA-NativeUserInput|cip.userio.InputManager:? - Received SOFT: 2
1850 NOT Jun 12 14:41:27.363375 (588:909) JAVA-NIOGetEvent: hard key event read
1851 INF Jun 12 14:41:27.363528 (588:909) JAVA-[[MESSAGE_1.0]]: [NativeIO] --> 5.2(release) --> [JAVA] :
1852 NOT Jun 12 14:41:27.363955 (588:909) JAVA-NativeUserInput|cip.userio.InputManager$NativeEventThread:? - Forwarding native input event
1853 INF Jun 12 14:41:27.364779 (588:909) JAVA-NativeUserInput|cip.userio.InputManager:? - Received SOFT: 2
1854 NOT Jun 12 14:41:27.387944 (370:383) PWRMAN-setMode(): NORMAL 
1855 NOT Jun 12 14:41:27.388554 (588:739) JAVA-Calling handlePowerManEvent
1856 NOT Jun 12 14:41:27.388829 (588:739) JAVA-Calling handlePowerManEvent
1857 DEB Jun 12 14:41:27.393407 kernel: [  216.566519] Set LCD backlight 1
1858 NOT Jun 12 14:41:28.200183 (588:909) JAVA-NIOGetEvent: hard key event read
1859 INF Jun 12 14:41:28.200366 (588:909) JAVA-[[MESSAGE_1.0]]: [NativeIO] --> 5.1(press) --> [JAVA] :
1860 NOT Jun 12 14:41:28.200762 (588:909) JAVA-NativeUserInput|cip.userio.InputManager$NativeEventThread:? - Forwarding native input event
1861 INF Jun 12 14:41:28.201617 (588:909) JAVA-NativeUserInput|cip.userio.InputManager:? - Received SOFT: 1
1862 NOT Jun 12 14:41:28.393407 (588:909) JAVA-NIOGetEvent: hard key event read
1863 INF Jun 12 14:41:28.393590 (588:909) JAVA-[[MESSAGE_1.0]]: [NativeIO] --> 5.1(release) --> [JAVA] :
1864 NOT Jun 12 14:41:28.393987 (588:909) JAVA-NativeUserInput|cip.userio.InputManager$NativeEventThread:? - Forwarding native input event
1865 INF Jun 12 14:41:28.395513 (588:909) JAVA-NativeUserInput|cip.userio.InputManager:? - Received SOFT: 1
1866 NOT Jun 12 14:41:28.403509 (370:383) PWRMAN-setMode(): NORMAL 
1867 NOT Jun 12 14:41:28.403876 (588:739) JAVA-Calling handlePowerManEvent
1868 NOT Jun 12 14:41:28.404120 (588:739) JAVA-Calling handlePowerManEvent
1869 DEB Jun 12 14:41:28.413367 kernel: [  217.582053] Set LCD backlight 1
1870 NOT Jun 12 14:41:29.576194 (588:909) JAVA-NIOGetEvent: hard key event read
1871 INF Jun 12 14:41:29.576377 (588:909) JAVA-[[MESSAGE_1.0]]: [NativeIO] --> 5.2(press) --> [JAVA] :
1872 NOT Jun 12 14:41:29.576743 (588:909) JAVA-NativeUserInput|cip.userio.InputManager$NativeEventThread:? - Forwarding native input event
1873 INF Jun 12 14:41:29.577567 (588:909) JAVA-NativeUserInput|cip.userio.InputManager:? - Received SOFT: 2
1874 NOT Jun 12 14:41:29.773416 (588:909) JAVA-NIOGetEvent: hard key event read
1875 INF Jun 12 14:41:29.773599 (588:909) JAVA-[[MESSAGE_1.0]]: [NativeIO] --> 5.2(release) --> [JAVA] :
1876 NOT Jun 12 14:41:29.773996 (588:909) JAVA-NativeUserInput|cip.userio.InputManager$NativeEventThread:? - Forwarding native input event
1877 INF Jun 12 14:41:29.774851 (588:909) JAVA-NativeUserInput|cip.userio.InputManager:? - Received SOFT: 2
1878 NOT Jun 12 14:41:29.783824 (370:383) PWRMAN-setMode(): NORMAL 
1879 NOT Jun 12 14:41:29.784190 (588:739) JAVA-Calling handlePowerManEvent
1880 NOT Jun 12 14:41:29.784434 (588:739) JAVA-Calling handlePowerManEvent
1881 NOT Jun 12 14:41:29.785411 (588:713) JAVA-System P5-traceManager MQThread|cip.sipcc.SipCcAdapter$CcMgmtListener:  - mgmtState=MGMT_DOWN(0)
1882 DEB Jun 12 14:41:29.790325 (588:713) JAVA-System P5-traceManager MQThread|cip.setg.newEditMenuModel:shouldDisplayTFTPChangeAlert - [shouldDisplayTFTPChangeAlert] menuName= IPv4 Configuration, tftp1Changed =false (10.10.1.10 -> 10.10.1.10), tftp2Changed =false (10.11.1.10 -> 10.11.1.10), otherTftp1 =::, otherTftp2 =::, dhcpenable-Changed =true, dhcpenabled =false, deviceMode =Enterprise (1), registered =false, oldTftpAvailable =true, newTftpAvailable =true, service mode:Enterprise, service state:idle
1883 DEB Jun 12 14:41:29.791362 (588:713) JAVA-System P5-traceManager MQThread|cip.setg.newEditMenuModel:shouldDisplayTFTPChangeAlert -  returns alert-reason: 0
1884 DEB Jun 12 14:41:29.793407 kernel: [  218.962276] Set LCD backlight 1
1885 DEB Jun 12 14:41:29.792888 (588:713) JAVA-System P5-traceManager MQThread|IPv4SettingModel:IPv4SettingModel - [shouldDisplayTLInstalledAlert] menuName= IPv4 Configuration, tftp1Changed: =false, tftp2Changed: =false, dhcpenable-Changed: =true, dhcpenabled?=false
1886 INF Jun 12 14:41:29.801007 (588:910) JAVA-System P7-display MQThread|cip.callui.market.OverviewModel:? - OverviewModel---------------------hasServer headSubPromptVal: false
1887 NOT Jun 12 14:41:29.872577 (588:928) JAVA-configmgr MQThread|ConfigManager:? - --->ConfigManager PropertyChanged: device.settings.network.hostipaddress
1888 NOT Jun 12 14:41:29.873767 (588:928) JAVA-configmgr MQThread|ConfigManager:? - [handleIpChange] Property "device.settings.network.hostipaddress" changed
1889 NOT Jun 12 14:41:29.874958 (588:928) JAVA-configmgr MQThread|ConfigManager:? - <---ConfigManager PropertyChanged: device.settings.network.hostipaddress
1890 DEB Jun 12 14:41:29.896078 (588:713) JAVA-System P5-traceManager MQThread|cip.setg.newEditMenuModel:applyValue -  >>> auto select accessMode, isTFTPAvailable-native=true isTFTPAvailable-java=true
1891 INF Jun 12 14:41:29.898336 (588:910) JAVA-System P7-display MQThread|cip.callui.market.OverviewModel:? - OverviewModel---------------------hasServer headSubPromptVal: false
1892 NOT Jun 12 14:41:29.975980 (588:928) JAVA-configmgr MQThread|ConfigManager:? - --->ConfigManager PropertyChanged: device.settings.network.hostipaddress
1893 NOT Jun 12 14:41:29.976438 (588:928) JAVA-configmgr MQThread|ConfigManager:? - [handleIpChange] Property "device.settings.network.hostipaddress" changed
1894 NOT Jun 12 14:41:29.976896 (588:928) JAVA-configmgr MQThread|ConfigManager:? - <---ConfigManager PropertyChanged: device.settings.network.hostipaddress
1895 DEB Jun 12 14:41:30.020936 (588:713) JAVA-disabledhcp(): pid: 588 
1896 DEB Jun 12 14:41:30.021181 (588:713) JAVA-disabledhcp(): netsdMsgQue:  path: /tmp/netsd_msg_que  key: 0x101004c4  que: 0x0  
1897 DEB Jun 12 14:41:30.021333 (588:713) JAVA-disabledhcp(): msgsnd() rc: 0, size: 12 bytes  
1898 NOT Jun 12 14:41:30.022127 (718:724) DHCP-dhcpDisable(): state: REQUESTING     
1899 DEB Jun 12 14:41:30.021425 (588:713) JAVA-disabledhcp(): retVal: 0  
1900 DEB Jun 12 14:41:30.032168 (588:713) JAVA-setdhcpinfo(): pid: 588 
1901 DEB Jun 12 14:41:30.034823 (588:713) JAVA-setdhcpinfo(): dhcpRetMsgQue:  path: /tmp/dhcp_ret_msg_que  key: 0x10100bc0  que: 0xa8015  
1902 DEB Jun 12 14:41:30.037967 (588:713) JAVA-setdhcpinfo(): msgsnd():  rc: 0  size: 1264 bytes  
1903 NOT Jun 12 14:41:30.049961 (332:389) NETSD-netsdSignal(): NETSD_EV_GW
1904 ERR Jun 12 14:41:30.050663 (359:359) PAE: -paeNetsdRcvMsg(359): unknown event: 0x8000  status: 0x0 : Network is down 
1905 NOT Jun 12 14:41:30.051152 (588:739) JAVA-Calling handleNetSDEvent
1906 NOT Jun 12 14:41:30.052006 (332:389) NETSD-netsdSignal(): EV_IP 
1907 NOT Jun 12 14:41:30.056676 (718:724) DHCP-/tmp/tftp.avail is being reset
1908 NOT Jun 12 14:41:30.083717 (332:389) NETSD-netsdSignal(): EV_IP : kill -26 `cat /var/run/ewcl.pid`  
1909 NOT Jun 12 14:41:30.084632 (359:359) PAE: -paeNetsdRcvMsg(359): IP change received: status: 0x0 : Network is down 
1910 NOT Jun 12 14:41:30.085243 (365:365) EWCLIENT-SIGVTALRM received
1911 NOT Jun 12 14:41:30.086128 (332:389) NETSD-netsdSignal(): EV_IP from DHCP
1912 NOT Jun 12 14:41:30.086677 (595:623) DHCP6: -process_command(): recv cmd 11
1913 NOT Jun 12 14:41:30.087196 (365:420) EWCLIENT-event(332): IP Event received from netsd
1914 NOT Jun 12 14:41:30.088264 (588:739) JAVA-Calling handleNetSDEvent
1915 NOT Jun 12 14:41:30.089729 (332:389) NETSD-netsdSignal(): EV_IP 
1916 NOT Jun 12 14:41:30.140271 (365:419) EWCLIENT-SIGVTALRM received
1917 NOT Jun 12 14:41:30.141339 (332:389) NETSD-netsdSignal(): EV_IP : kill -26 `cat /var/run/ewcl.pid`  
1918 NOT Jun 12 14:41:30.141980 (359:359) PAE: -paeNetsdRcvMsg(359): IP change received: status: 0x0 : Network is down 
1919 NOT Jun 12 14:41:30.143079 (332:389) NETSD-netsdSignal(): EV_IP from DHCP
1920 DEB Jun 12 14:41:30.143659 (588:713) JAVA-setdhcpinfo(): msgrcv() 12 bytes  
1921 DEB Jun 12 14:41:30.143842 (588:713) JAVA-setdhcpinfo(): retVal: 0  
1922 DEB Jun 12 14:41:30.144269 (588:713) JAVA-setdhcpinfo(): pid: 588 
1923 DEB Jun 12 14:41:30.144483 (588:713) JAVA-setdhcpinfo(): dhcpRetMsgQue:  path: /tmp/dhcp_ret_msg_que  key: 0x10100bc0  que: 0xa8015  
1924 DEB Jun 12 14:41:30.144697 (588:713) JAVA-setdhcpinfo(): msgsnd():  rc: 0  size: 1264 bytes  
1925 NOT Jun 12 14:41:30.169937 (365:365) EWCLIENT-ewclmain: IP changed 
1926 NOT Jun 12 14:41:30.190813 (595:623) DHCP6: -process_command(): recv cmd 11
1927 NOT Jun 12 14:41:30.212757 (365:420) EWCLIENT-netsdipevent(): WIRED addr: 10.10.4.111  
1928 NOT Jun 12 14:41:30.213154 (365:420) EWCLIENT-event(332): IP Event received from netsd
1929 NOT Jun 12 14:41:30.234091 (429:429) CDP-netsdipevent(): WIRED addr: 10.10.4.111  
1930 NOT Jun 12 14:41:30.255882 (365:419) EWCLIENT-ewclmain: IP no change 
1931 WRN Jun 12 14:41:30.256126 (365:419) EWCLIENT-ewcl_eventThrd(): select() failed EINTR 
1932 NOT Jun 12 14:41:30.258721 (718:724) DHCP-/tmp/tftp.avail is being reset
1933 NOT Jun 12 14:41:30.302365 (429:429) CDP-netsdipevent(): ipmode = 0 
1934 NOT Jun 12 14:41:30.303158 (365:420) EWCLIENT-netsdipevent(): WIRED addr: 10.10.4.111  
1935 NOT Jun 12 14:41:30.324523 (332:389) NETSD-netsdSignal(): EV_IP 
1936 NOT Jun 12 14:41:30.352327 (365:365) EWCLIENT-SIGVTALRM received
1937 NOT Jun 12 14:41:30.352784 (332:389) NETSD-netsdSignal(): EV_IP : kill -26 `cat /var/run/ewcl.pid`  
1938 NOT Jun 12 14:41:30.354188 (359:359) PAE: -paeNetsdRcvMsg(359): IP change received: status: 0x0 : Network is down 
1939 NOT Jun 12 14:41:30.354860 (332:389) NETSD-netsdSignal(): EV_IP from DHCP
1940 NOT Jun 12 14:41:30.355318 (595:623) DHCP6: -process_command(): recv cmd 11
1941 NOT Jun 12 14:41:30.355745 (365:420) EWCLIENT-event(332): IP Event received from netsd
1942 DEB Jun 12 14:41:30.356844 (588:713) JAVA-setdhcpinfo(): msgrcv() 12 bytes  
1943 DEB Jun 12 14:41:30.357027 (588:713) JAVA-setdhcpinfo(): retVal: 0  
1944 DEB Jun 12 14:41:30.365115 (588:713) JAVA-setipmode(): pid = 588 
1945 DEB Jun 12 14:41:30.367343 (588:713) JAVA-setipmode(): NETSD_MESSAGE_QUE: key->0x101004c4 mode = 0
1946 DEB Jun 12 14:41:30.367800 (588:713) JAVA-setipmode(): msgsnd() rc: 0, size: 8 bytes  
1947 ERR Jun 12 14:41:30.391057 (588:713) JAVA-System P5-traceManager MQThread|cip.app.AppFrame:startNotification - Notification: Change Accepted and Savedcan't be display in status prompt
1948 NOT Jun 12 14:41:30.415168 (429:429) CDP-netsdipevent(): WIRED addr: 10.10.4.111  
1949 NOT Jun 12 14:41:30.443796 (588:924) JAVA-callagent MQThread|cip.callagent.CallAgent$2:? - resetData:resetState:RE_DHCP_REQUEST registrationState:NORMAL dhcpOption:DHCPv4_DISABLED_DHCPv6_ENABLED deadIpStack:-1showDefer:true, requested:true, pending:false, paused:false
1950 DEB Jun 12 14:41:30.446787 (588:924) JAVA-callagent MQThread|cip.callagent.CallAgent:? - resetData:resetState:RE_DHCP_REQUEST registrationState:NORMAL dhcpOption:DHCPv4_DISABLED_DHCPv6_ENABLED deadIpStack:-1showDefer:true, requested:true, pending:false, paused:false
1951 NOT Jun 12 14:41:30.450785 (588:910) JAVA-System P7-display MQThread|cip.sipcc.SipCcAdapter$CcMgmtListener:  - readyToRegister(): called. mgmtState=MGMT_DOWN(0)
1952 NOT Jun 12 14:41:30.460582 (588:924) JAVA-callagent MQThread|cip.callagent.CallAgent$2:? - resetData:resetState:RE_DHCP_PENDING registrationState:STOP dhcpOption:DHCPv4_DISABLED_DHCPv6_ENABLED deadIpStack:-1showDefer:true, requested:false, pending:true, paused:false
1953 NOT Jun 12 14:41:30.467083 (588:928) JAVA-configmgr MQThread|ConfigManager:? - [redhcp] IPv4: SET DHCP DISABLED, IPv6: SET DHCP6 FAST
1954 NOT Jun 12 14:41:30.471295 (588:713) JAVA-System P5-traceManager MQThread|cip.l10n.LocalizationManager$1: - LocaleManager detect propety changed: device.settings.network.ipstacksstate
1955 NOT Jun 12 14:41:30.473493 (588:928) JAVA-configmgr MQThread|HttpTask:? - [ensureSystemUrlIsValid] => urlTitle:PROXY URL, url:http://, ip-addressing-mode:Both (IPv4 and IPv6)
1956 NOT Jun 12 14:41:30.480360 (588:917) JAVA-HTTP JNI| Java_cip_http_NativeHttpTask_updateProxyServerURL: setting ProxyServerUrl to []
1957 NOT Jun 12 14:41:30.481275 (588:928) JAVA-configmgr MQThread|cip.http.HttpTask:? - auth url is http://10.10.1.18:8081/InformaCast/phone/auth
1958 NOT Jun 12 14:41:30.482221 (588:928) JAVA-configmgr MQThread|HttpTask:? - [ensureSystemUrlIsValid] => urlTitle:AUTHENTICATION URL, url:http://10.10.1.18:8081/InformaCast/phone/auth, ip-addressing-mode:Both (IPv4 and IPv6)
1959 NOT Jun 12 14:41:30.482862 (588:713) JAVA-System P5-traceManager MQThread|cip.l10n.LocalizationManager:? - [handleIpStackFailure] IpStacksStateProperty changed to IPv4-stack-state:-1 (SET DHCP DISABLED), IPv6-stack-state:0 (SET DHCP6 FAST),localeFilesAreDownloading:false
1960 NOT Jun 12 14:41:30.484083 (588:917) JAVA-HTTP JNI| Java_cip_http_NativeHttpTask_updateAuthenticationURL: setting AuthUrl to [http://10.10.1.18:8081/InformaCast/phone/auth]
1961 INF Jun 12 14:41:30.486189 (588:910) JAVA-System P7-display MQThread|cip.callui.market.OverviewModel:? - OverviewModel---------------------hasServer headSubPromptVal: false
1962 NOT Jun 12 14:41:30.501052 (588:928) JAVA-restartdhcp6(): send to socket successfully
1963 NOT Jun 12 14:41:30.524736 (588:910) JAVA-System P7-display MQThread|cip.sipcc.SipCcAdapter:  - propertyChanged(): device.settings.network.ipstacksstate
1964 NOT Jun 12 14:41:30.526049 (588:910) JAVA-System P7-display MQThread|cip.sipcc.SipCcAdapter:  - [propertyChanged] IpStacksStateProperty changed to IPv4-stack-state:-1 (SET DHCP DISABLED), IPv6-stack-state:0 (SET DHCP6 FAST)
1965 INF Jun 12 14:41:30.527849 (588:910) JAVA-System P7-display MQThread|cip.sipcc.SipCcAdapter:  - device.settings.network.ipstacksstate=IPv4-stack-state:-1 (SET DHCP DISABLED), IPv6-stack-state:0 (SET DHCP6 FAST),registered-ip-stack

Thank you in advance for any help offered.

Jason Giles

Mohamed Amine Jaafar · ‎06-12-2018

This is indeed a weird issue. Did you try to change the patch cable ? Many times I found myself with a cable which has working Power pairs but faulty network ones.

Also, from the logs you posted, I don't think that your "IP phone gets its correct network information from the DHCP server".

Your IP phone is not receiving answers for DHCPDISCOVER and DHCPREQUEST messages, according to logs.

Double check the DHCP server too.

jsgilesbv2012 · ‎06-14-2018

Thank you! I noticed that same thing in the logs, however, the DHCP server all seems to be fine and has been in place for a long time. I did restart it.. no change.. my 7942 phones register just fine. the DHCP server Im using is an older server 2003 server. Starting to think maybe its time to build a new DHCP server for the phone system to support the newer phones.

pqueued · ‎06-12-2018

Can you try a different firmware version to see if the issue is resolved. I have hit a similar bug previously that was firmware related.