System date sudden change

sundar63 · June 16, 2010, 11:32pm

Hi there,

We have a Solaris 10 machine which has been up and running for more than 400 days. A strange behaviour happened. The system date defaulted to epoch timestamp. Oracle stopped and application failed causing management to parade. We managed to reset the date. All other servers and including the problem one are synced with ntp server.

My question is how to investigate the sudden change in system date?
What caused it to go haywire? There is nothing in the logs to indicate anyone modified anything.

Below is an excerpt of messages:

Jun 16 03:40:50 serversun xmsTrigger: [ID 839465 user.notice]
xmsTrigger(18788) NOTICE: Path ptx:0 prx:0 ltx:3 lrx:0 'MMX_REDIRECT_serversun' 
Jun 16 03:40:50 serversun xmsTrigger: [ID 839465 user.notice]
xmsTrigger(18788) NOTICE: Path ptx:0 prx:0 ltx:0 lrx:1 'MMX_REDIRECT_serversun4' 
Jun 16 03:40:50 serversun xmsTrigger: [ID 839465 user.notice]
xmsTrigger(18788) NOTICE: Path ptx:0 prx:0 ltx:0 lrx:1 'MMX_REDIRECT_serversun1' 
Jun 16 03:40:50 serversun xmsTrigger: [ID 839465 user.notice]
xmsTrigger(18788) NOTICE: Path ptx:0 prx:0 ltx:0 lrx:1 'MMX_REDIRECT_serversun2' 
Jun 16 03:40:51 serversun xmsTrigger: [ID 839465 user.notice]
xmsTrigger(18788) NOTICE: Maximum SMS/s rate in the last period: 2 Jun 16 03:40:54 serversun sua_if: [ID 761583 user.error] sua_if(18789) ERROR =11 TcSccpCommonInterface.cc564:  Unrecognised Transaction ID received (29480), TCAP Type (101) Jun 16 03:40:54 serversun sua_if: [ID 761583 user.error] sua_if(18789) ERROR =11 TcSccpCommonInterface.cc564:  Unrecognised Transaction ID received (29480), TCAP Type (101) Jun 16 03:41:04 serversun sua_if: [ID 761583 user.error] sua_if(18789) ERROR =11 TcSccpCommonInterface.cc564:  Unrecognised Transaction ID received (28438), TCAP Type (101) Jun 16 03:41:04 serversun sua_if: [ID 761583 user.error] sua_if(18789) ERROR =11 TcSccpCommonInterface.cc564:  Unrecognised Transaction ID received (28438), TCAP Type (101) Jun 16 03:41:06 serversun xmsTrigger: [ID 839465 user.notice]
xmsTrigger(18788) NOTICE: Maximum SMS/s rate in the last period: 2 Jun 16 03:41:17 serversun last message repeated 1 time Jun 16 03:41:26 serversun xmsTrigger: [ID 839465 user.notice]
xmsTrigger(18788) NOTICE: Your system is running within allowed limits (maximum concurrent calls: 1000, currently: 1; maximum SMS/sec: 1000, currently 2) Jun 16 03:41:27 serversun xmsTrigger: [ID 839465 user.notice]
xmsTrigger(18788) NOTICE: Maximum SMS/s rate in the last period: 2 Jun 16 03:41:47 serversun last message repeated 2 times Nov  5 22:17:32 serversun diameterBeClient: [ID 839465 user.notice]
diameterBeClient(18795) NOTICE: {970020} DCD DIAMETER_MIN_LATENCY in the last period for host sunsvr was 3748 Nov  5 22:17:32 serversun diameterBeClient: [ID 839465 user.notice]
diameterBeClient(18795) NOTICE: {970021} DCD DIAMETER_MAX_LATENCY in the last period for host sunsvr was 114060 Nov  5 22:17:32 serversun diameterBeClient: [ID 839465 user.notice]
diameterBeClient(18795) NOTICE: {970022} DCD DIAMETER_AVERAGE_LATENCY in the last period for host sunsvr was 7036 Nov  5 22:17:32 serversun oraPStoreCleaner: [ID 839465 user.notice]
oraPStoreCleaner(2103) NOTICE: Shutting down from daemon mode.
Nov  5 22:17:33 serversun oraPStoreCleaner: [ID 761583 user.error]
oraPStoreCleaner(2103) ERROR Oracle=-3113 oraConnect.pc@231: delete  from cmn_persistent_store  where date_inserted<=TO_DATE(:b0,'Y: ORA-03113:
end-of-file on communication channel                       
Nov  5 22:17:33 serversun oraPStoreCleaner: [ID 761583 user.error]
oraPStoreCleaner(2103) ERROR Oracle=-3113 oraConnect.pc@231: delete  from cmn_persistent_store  where date_inserted<=TO_DATE(:b0,'Y: ORA-03113:
end-of-file on communication channel                       
Nov  5 22:17:33 serversun UssdMfileD: [ID 438867 user.warning]
UssdMfileD(2105) WARNING OEXEC, OEXN=3113 cmnMfileDaemonApi.cc@612: ORA-03113:
end-of-file on communication channel
Nov  5 22:17:33 serversun UssdMfileD: [ID 438867 user.warning]
UssdMfileD(2106) WARNING OEXEC, OEXN=3113 cmnMfileDaemonApi.cc@612: ORA-03113:
end-of-file on communication channel
Nov  5 22:17:33 serversun slee_acs: [ID 675952 user.error] slee_acs(18780)
ERROR: CCS LoadService: Error getting account data (by CLI) Nov  5 22:17:33 serversun slee_acs: [ID 675952 user.error] slee_acs(18780)
ERROR: CCS LoadService: Error getting account data (by CLI) Nov  5 22:17:33 serversun slee_acs: [ID 675952 user.error] slee_acs(18780)
ERROR: ORACLE error--
Nov  5 22:17:33 serversun slee_acs: [ID 675952 user.error] slee_acs(18780)
ERROR: ORACLE error--
Nov  5 22:17:33 serversun slee_acs: [ID 675952 user.error] slee_acs(18780)
ERROR: ORA-03114: not connected to ORACLE Nov  5 22:17:33 serversun slee_acs: [ID 675952 user.error] slee_acs(18780)
ERROR: ORA-03114: not connected to ORACLE Nov  5 22:17:33 serversun slee_acs: [ID 953149 user.warning]
slee_acs(18780) WARNING: acsChassisPerformLoad: CCS - no call plan found (CLN '502181071854383', CPN '60182672937') Nov  5 22:17:33 serversun slee_acs: [ID 675952 user.error] slee_acs(18780)
ERROR: CCS LoadService: Error getting account data (by CLI) Nov  5 22:17:33 serversun slee_acs: [ID 675952 user.error] slee_acs(18780)
ERROR: CCS LoadService: Error getting account data (by CLI) Nov  5 22:17:33 serversun slee_acs: [ID 675952 user.error] slee_acs(18780)
ERROR: ORACLE error--
Nov  5 22:17:33 serversun slee_acs: [ID 675952 user.error] slee_acs(18780)
ERROR: ORACLE error--
Nov  5 22:17:33 serversun slee_acs: [ID 675952 user.error] slee_acs(18780)
ERROR: ORA-03114: not connected to ORACLE Nov  5 22:17:33 serversun slee_acs: [ID 675952 user.error] slee_acs(18780)
ERROR: ORA-03114: not connected to ORACLE Nov  5 22:17:33 serversun slee_acs: [ID 953149 user.warning]
slee_acs(18780) WARNING: acsChassisPerformLoad: CCS - no call plan found (CLN '502181071736437', CPN '60189628114') Nov  5 22:17:33 serversun slee_acs: [ID 675952 user.error] slee_acs(18780)
ERROR: CCS LoadService: Error getting account data (by CLI) Nov  5 22:17:33 serversun slee_acs: [ID 675952 user.error] slee_acs(18780)
ERROR: CCS LoadService: Error getting account data (by CLI) Nov  5 22:17:33 serversun slee_acs: [ID 675952 user.error] slee_acs(18780)
ERROR: ORACLE error--
Nov  5 22:17:33 serversun slee_acs: [ID 675952 user.error] slee_acs(18780)
ERROR: ORACLE error--
Nov  5 22:17:33 serversun slee_acs: [ID 675952 user.error] slee_acs(18780)
ERROR: ORA-03114: not connected to ORACLE Nov  5 22:17:33 serversun slee_acs: [ID 675952 user.error] slee_acs(18780)
ERROR: ORA-03114: not connected to ORACLE Nov  5 22:17:33 serversun slee_acs: [ID 953149 user.warning]
slee_acs(18780) WARNING: acsChassisPerformLoad: CCS - no call plan found (CLN '502181072000755', CPN '60182648809') Jan  1 00:00:01 serversun diameterBeClient: [ID 839465 user.notice]
diameterBeClient(18795) NOTICE: {970020} DCD DIAMETER_MIN_LATENCY in the last period for host sunsvr was 694 Jan  1 00:00:01 serversun diameterBeClient: [ID 839465 user.notice]
diameterBeClient(18795) NOTICE: {970021} DCD DIAMETER_MAX_LATENCY in the last period for host sunsvr was 9492 Jan  1 00:00:01 serversun diameterBeClient: [ID 839465 user.notice]
diameterBeClient(18795) NOTICE: {970022} DCD DIAMETER_AVERAGE_LATENCY in the last period for host sunsvr was 2910 Jan  1 00:00:01 serversun xmsTrigger: [ID 839465 user.notice]
xmsTrigger(18788) NOTICE: Your system is running within allowed limits (maximum concurrent calls: 1000, currently: 1; maximum SMS/sec: 1000, currently 1) Jan  1 00:00:01 serversun slee_acs: [ID 953149 user.warning]
slee_acs(18780) WARNING: ccs_getGlobalCapabilities: Error retrieving capabilities.
Jan  1 00:00:01 serversun sua_if: [ID 761583 user.error] sua_if(18789) ERROR =11 TcSccpCommonInterface.cc564:  Unrecognised Transaction ID received (32614), TCAP Type (101) Jan  1 00:00:01 serversun sua_if: [ID 761583 user.error] sua_if(18789) ERROR =11 TcSccpCommonInterface.cc564:  Unrecognised Transaction ID received (32614), TCAP Type (101) Jan  1 00:00:01 serversun oraPStoreCleaner: [ID 675952 user.error]
oraPStoreCleaner(11491) ERROR: Could not connect to the database Jan  1 00:00:01 serversun oraPStoreCleaner: [ID 675952 user.error]
oraPStoreCleaner(11491) ERROR: Could not connect to the database Jan  1 00:00:02 serversun slee_acs: [ID 953149 user.warning]
slee_acs(18781) WARNING: ccs_getGlobalCapabilities: Error retrieving capabilities.
Jan  1 00:00:02 serversun oraPStoreCleaner: [ID 675952 user.error]
oraPStoreCleaner(11497) ERROR: Could not connect to the database Jan  1 00:00:02 serversun oraPStoreCleaner: [ID 675952 user.error]
oraPStoreCleaner(11497) ERROR: Could not connect to the database Jan  1 00:00:02 serversun oraPStoreCleaner: [ID 675952 user.error]
oraPStoreCleaner(11503) ERROR: Could not connect to the database Jan  1 00:00:02 serversun oraPStoreCleaner: [ID 675952 user.error]
oraPStoreCleaner(11503) ERROR: Could not connect to the database ....

Can anyone tell where to start?

Thanks for your help.

garskoci · June 17, 2010, 3:31pm

What model server is it?

Scott · June 17, 2010, 3:46pm

Hi.

Could an admin have modified the date (using date(1). That could certainly screw up Oracle if going backwards. A corrupt /etc/utmp file would show very long uptime, but not sure if that would cause Oracle any problems (and in any case would correct itself after a reboot).

sundar63 · June 18, 2010, 12:50am

Thank you for the responses.
@garskoci
The model is:
SunOS ..Generic_120011-14 sun4u sparc SUNW,Sun-Fire-V440

@scottn
"Could an admin have modified the date " No.
The usual system logs doesn't show any useful information.

busyboy · June 18, 2010, 5:23am

possible causes:

someone might have logged onto this system and changed the time :

the battery might have gone wild on sys-board

the application has caused this weird behavior

incredible · June 19, 2010, 8:09am

is your system using any NTP setup?

sundar63 · June 19, 2010, 12:39pm

Good question.

Yes. there are many other servers syncing with the same NTP server.
Unfortunately this one misbehaved. I am suspecting the application
which may have back dated data as transaction id in the TCAP packet. Well, it's a wild guess.

garskoci · June 20, 2010, 12:15am

Hmmmm.... I've seen this happen with Sun Fire 4800, 6800 etc. family. But, not the v440's. In that case there was a bug in the firmware. It was an issue with the Serengeti clock driver.

This sounds like a similar issue.

busyboy · June 21, 2010, 1:32am

incredible :

if this was as a result of NTP in any case, it must have something in messages file , but here in the OP I don't see any such message.

Regards,
BB