Upgrade to Thingworx 8.0 Errors

[bmessenger]

HI,

I have followed all the instructions in this document http://support.ptc.com/WCMS/files/173117/en/Upgrading_to_ThingWorx_8.0_1.0.pdf but with no luck.

Tomcat starts and I get errors in tomcat and Thingworx, when I try to go to localhost:9080/Thingworx. I know tomcat is fine because we have another site on the same server. (Well I know it is not a tomcat configuration error, and also Thingworx 7.3 worked on the same installation).

The Thingworx security log says

2017-06-27 16:23:19.062+1000 [L: INFO] [O: S.c.t.s.a.s.SSOContext] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] SSOContext created...

2017-06-27 16:23:19.175+1000 [L: ERROR] [O: S.c.t.s.a.AuthenticationFilter] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] Could not load session timeout from database, using default: null

2017-06-27 16:23:19.186+1000 [L: INFO] [O: S.c.t.s.s.SCIMProvider] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] Initializing SCIMProvider servlet...

2017-06-27 16:23:19.189+1000 [L: ERROR] [O: S.c.t.s.s.SCIMProvider] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] SCIMProvider initialization failure.  Thingworx Server is not running

2017-06-27 16:23:27.067+1000 [L: ERROR] [O: S.c.t.s.a.AuthenticationFilter] [I: ] [U: ] [S: ] [T: http-nio-9080-exec-7] Could not handle request

The Thingworx application log says

2017-06-27 16:23:17.847+1000 [L: INFO] [O: c.t.s.ThingWorxBootstrapper] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] ========================================

2017-06-27 16:23:17.850+1000 [L: INFO] [O: c.t.s.ThingWorxBootstrapper] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] ThingWorx Version Information

2017-06-27 16:23:17.850+1000 [L: INFO] [O: c.t.s.ThingWorxBootstrapper] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] ========================================

2017-06-27 16:23:17.855+1000 [L: INFO] [O: c.t.s.ThingWorxBootstrapper] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] majorVersion = 8

2017-06-27 16:23:17.856+1000 [L: INFO] [O: c.t.s.ThingWorxBootstrapper] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] minorVersion = 0

2017-06-27 16:23:17.856+1000 [L: INFO] [O: c.t.s.ThingWorxBootstrapper] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] revision = 0

2017-06-27 16:23:17.856+1000 [L: INFO] [O: c.t.s.ThingWorxBootstrapper] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] build = b11

2017-06-27 16:23:17.859+1000 [L: INFO] [O: c.t.s.ThingWorxBootstrapper] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] schemaVersion = 1000

2017-06-27 16:23:17.859+1000 [L: INFO] [O: c.t.s.ThingWorxBootstrapper] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] ========================================

2017-06-27 16:23:17.859+1000 [L: INFO] [O: c.t.s.ThingWorxBootstrapper] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] ========================================

2017-06-27 16:23:17.860+1000 [L: INFO] [O: c.t.s.ThingWorxBootstrapper] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] ThingWorx System Environment Settings

2017-06-27 16:23:17.860+1000 [L: INFO] [O: c.t.s.ThingWorxBootstrapper] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] ========================================

2017-06-27 16:23:17.860+1000 [L: INFO] [O: c.t.s.ThingWorxBootstrapper] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] OS: Windows Server 2008 R2

2017-06-27 16:23:17.860+1000 [L: INFO] [O: c.t.s.ThingWorxBootstrapper] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] OS arch: amd64

2017-06-27 16:23:17.860+1000 [L: INFO] [O: c.t.s.ThingWorxBootstrapper] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] OS version: 6.1

2017-06-27 16:23:17.861+1000 [L: INFO] [O: c.t.s.ThingWorxBootstrapper] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] Total Processors: 4

2017-06-27 16:23:17.862+1000 [L: INFO] [O: c.t.s.ThingWorxBootstrapper] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] Default encoding: windows-1252

2017-06-27 16:23:17.862+1000 [L: INFO] [O: c.t.s.ThingWorxBootstrapper] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] JAVA vendor: Oracle Corporation

2017-06-27 16:23:17.862+1000 [L: INFO] [O: c.t.s.ThingWorxBootstrapper] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] JAVA version: 1.8.0_131

2017-06-27 16:23:17.862+1000 [L: INFO] [O: c.t.s.ThingWorxBootstrapper] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] JAVA install location: C:\Program Files\Java\jre1.8.0_131

2017-06-27 16:23:17.862+1000 [L: INFO] [O: c.t.s.ThingWorxBootstrapper] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] JVM Max Memory: 228 (MB)

2017-06-27 16:23:17.862+1000 [L: INFO] [O: c.t.s.ThingWorxBootstrapper] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] ========================================

2017-06-27 16:23:17.862+1000 [L: INFO] [O: c.t.s.ThingWorxBootstrapper] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] WebApp starting...

2017-06-27 16:23:17.863+1000 [L: WARN] [O: c.t.s.ThingWorxBootstrapper] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] Please note.  Default character is set to Cp1252.  It should be [UTF-8]. Please use the VM argument [-Dfile.encoding=UTF-8] in your application server startup script

2017-06-27 16:23:18.315+1000 [L: INFO] [O: c.t.s.ThingWorxServer] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] HA mode not enabled. Initializing and starting in standalone mode.

2017-06-27 16:23:18.316+1000 [L: INFO] [O: c.t.s.ThingWorxPersistenceHandler] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] Default Persistence Provider Name = ThingworxPersistenceProvider

2017-06-27 16:23:18.316+1000 [L: INFO] [O: c.t.s.ThingWorxPersistenceHandler] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] Default Persistence Provider Package Name = PostgresPersistenceProviderPackage

2017-06-27 16:23:18.331+1000 [L: INFO] [O: c.t.p.p.PostgresDatasource] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] Reading configuration from configTableCol

2017-06-27 16:23:18.647+1000 [L: INFO] [O: c.t.s.ThingWorxServer] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] Managers...INITIALIZED

2017-06-27 16:23:18.651+1000 [L: INFO] [O: c.t.s.ThingWorxServer] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] Database initialization started...

2017-06-27 16:23:18.994+1000 [L: ERROR] [O: c.t.p.p.PostgresModelExceptionTranslator] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] [message: ERROR: duplicate key value violates unique constraint "root_entity_collection_pkey"_  Detail: Key (name)=(NotificationDefinitions) already exists.]

2017-06-27 16:23:18.997+1000 [L: ERROR] [O: c.t.p.p.PostgresDocumentModelDriver] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] Problems migrating database

2017-06-27 16:23:18.998+1000 [L: INFO] [O: c.t.s.ThingWorxServer] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] System ownership locking started...

2017-06-27 16:23:19.008+1000 [L: INFO] [O: c.t.s.ThingWorxServer] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] System ownership locking complete

2017-06-27 16:23:19.010+1000 [L: WARN] [O: c.m.v.c.i.NewPooledConnection] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] [c3p0] A PooledConnection that has already signalled a Connection error is still in use!

2017-06-27 16:23:19.010+1000 [L: WARN] [O: c.m.v.c.i.NewPooledConnection] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] [c3p0] Another error has occurred [ org.postgresql.util.PSQLException: ERROR: current transaction is aborted, commands ignored until end of transaction block ] which will not be reported to listeners!

2017-06-27 16:23:19.011+1000 [L: ERROR] [O: c.t.p.p.PostgresModelExceptionTranslator] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] [message: ERROR: current transaction is aborted, commands ignored until end of transaction block]

2017-06-27 16:23:19.011+1000 [L: ERROR] [O: c.t.s.ThingWorxServer] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] [message: ERROR: current transaction is aborted, commands ignored until end of transaction block]

2017-06-27 16:23:19.021+1000 [L: INFO] [O: c.t.p.p.PersistenceProvider] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] Connection ThingworxPersistenceProvider, type PostgresPersistenceProviderPackage stopped

2017-06-27 16:23:19.022+1000 [L: WARN] [O: c.t.p.p.PersistenceProvider] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] Could not find persistenceProviderPackage PostgresPersistenceProviderPackage and thus could not stop data processing

2017-06-27 16:23:19.027+1000 [L: ERROR] [O: c.t.s.ThingWorxBootstrapper] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] [message: Unable to initialize and start system: ERROR: current transaction is aborted, commands ignored until end of transaction block]

2017-06-27 16:23:19.028+1000 [L: ERROR] [O: c.t.s.ThingWorxBootstrapper] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] *** Web Application STATE is being set to ERROR! ***

2017-06-27 16:23:27.068+1000 [L: ERROR] [O: c.t.s.a.AuthenticationFilter] [I: ] [U: ] [S: ] [T: http-nio-9080-exec-7] Could not handle request

And the tomcat8-stderr.log file says

27-Jun-2017 15:22:17.225 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive C:\WebRoot\Regain.war has finished in 10,535 ms

27-Jun-2017 15:22:17.231 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployWAR Deploying web application archive C:\WebRoot\Thingworx.war

System property [org.owasp.esapi.opsteam] is not set

System property [org.owasp.esapi.devteam] is not set

[Fatal Error] :1:1: Premature end of file.

[Fatal Error] :1:1: Premature end of file.l

Any hints as to what the problem could be please? I really want to create my own extensions but the extension plug-in for Eclipse only supports 8.0 upwards, so I need to upgrade. Plus no doubt there are some nice new features I could use.

I'm using Postgresql, if that has any bearing.

I've since tried a few other things and I have what I think is a more meaningful message. In the

Application Log

2017-06-27 17:18:14.692+1000 [L: ERROR] [O: c.t.p.p.PostgresModelExceptionTranslator] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] [message: ERROR: duplicate key value violates unique constraint "root_entity_collection_pkey"_  Detail: Key (name)=(NotificationDefinitions) already exists.]

2017-06-27 17:18:14.695+1000 [L: ERROR] [O: c.t.p.p.PostgresDocumentModelDriver] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] Problems migrating database

2017-06-27 17:18:14.695+1000 [L: INFO] [O: c.t.s.ThingWorxServer] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] System ownership locking started...

2017-06-27 17:18:14.711+1000 [L: INFO] [O: c.t.s.ThingWorxServer] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] System ownership locking complete

2017-06-27 17:18:14.714+1000 [L: WARN] [O: c.m.v.c.i.NewPooledConnection] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] [c3p0] A PooledConnection that has already signalled a Connection error is still in use!

2017-06-27 17:18:14.715+1000 [L: WARN] [O: c.m.v.c.i.NewPooledConnection] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] [c3p0] Another error has occurred [ org.postgresql.util.PSQLException: ERROR: current transaction is aborted, commands ignored until end of transaction block ] which will not be reported to listeners!

2017-06-27 17:18:14.716+1000 [L: ERROR] [O: c.t.p.p.PostgresModelExceptionTranslator] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] [message: ERROR: current transaction is aborted, commands ignored until end of transaction block]

2017-06-27 17:18:14.717+1000 [L: ERROR] [O: c.t.s.ThingWorxServer] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] [message: ERROR: current transaction is aborted, commands ignored until end of transaction block]

2017-06-27 17:18:14.730+1000 [L: INFO] [O: c.t.p.p.PersistenceProvider] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] Connection ThingworxPersistenceProvider, type PostgresPersistenceProviderPackage stopped

2017-06-27 17:18:14.730+1000 [L: WARN] [O: c.t.p.p.PersistenceProvider] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] Could not find persistenceProviderPackage PostgresPersistenceProviderPackage and thus could not stop data processing

2017-06-27 17:18:14.733+1000 [L: ERROR] [O: c.t.s.ThingWorxBootstrapper] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] [message: Unable to initialize and start system: ERROR: current transaction is aborted, commands ignored until end of transaction block]

2017-06-27 17:18:14.733+1000 [L: ERROR] [O: c.t.s.ThingWorxBootstrapper] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] *** Web Application STATE is being set to ERROR! ***

2017-06-27 17:19:00.135+1000 [L: ERROR] [O: c.t.s.a.AuthenticationFilter] [I: ] [U: ] [S: ] [T: http-nio-9080-exec-6] Could not handle request

I don;t know how the database works exactly, but this would appear that Thingworx on starting is trying to insert into a table root_entity_collection with a primary key value for column pid that already exists.But I cannot see why or how that is happening.

Regards

Ben

Message was edited by: Ben Messenger

[tschmitz]

Hi Ben Messenger​,

Let's take a quick look at your database to see if the numbers match up to what it's saying in the logs above.  Please run the following queries, and let us know the results:

select count(*) from root_entity_collection;

select * from root_entity_collection_pid_seq;

Just a quick note for anyone else who stumbles across this, to run these queries in Postgres, open the pgAdmin III program where Postgres is installed, Under Servers -> PostgreSQL (version) -> Databases, select your thingworx database, and then click the 'Execute arbitrary SQL Queries' icon (it's a magnifying glass with SQL inside it).

Regards,

Tony

[bmessenger · Accepted solution]

Hi Tony,

Thanks for the response, but I had actually done what you suggested and it does not help. The issue is because the primary key on that table is not the ID (columnm pid) but the column "name". If you look at the count I have 35 records and the next sequence is actually 45, and there is no attempt to insert a record with the same pid, but as that is not the primary key it may not matter anyway.

After much gnashing of teeth I have found the cause of why Thingworx will not start. And the error actually gives us more information than I first thought. I find 4 issues with error logs in general

1. Where do you find the log files on the system. It is not often clear where they are.

2. Which log file is giving some pertinent information. Here is could have been one of several tomcat log files, or one of several Thingworx log files.

3. When you find the right log file, what actual information in the thousands of lines in the log is telling us about the error.

4. When you find the error, what is the actual error message telling us. Often, it tells us the right information, but you typically don't know this until you have solved it. (Which was the case here)

I realised the error was due to Thingworx and not tomcat, because we have a second website on the same tomcat instance and it would work until the Thingworx error surfaced and locked tomcat (well I think tomcat just doesn't have the resources to work efficiently rather than being locked out.). So that narrowed it down to the several Thingworx logs. Then you have to look through them and try and find what is the right info to concentrate on. That actually took a few hours to find, as my initial discussion point shows.

The error says

2017-06-27 17:18:14.692+1000 [L: ERROR] [O: c.t.p.p.PostgresModelExceptionTranslator] [I: ] [U: SuperUser] [S: ] [T: localhost-startStop-1] [message: ERROR: duplicate key value violates unique constraint "root_entity_collection_pkey"_  Detail: Key (name)=(NotificationDefinitions) already exists.]

This is actually telling us that the record with name NotificationDefinitions in the table root_entity_collection already exists and attempting to insert a second record with the same name fails and the database gets locked. So what I did was go into that table through pgAdmin III and changed the name to NotificationDefinitions_old, just in case this record I required later. I also found that the record with name NotificationContents also had to be changed and once again I just put an _old suffix onto the end. Once I did this I restarted tomcat, because it was still dealing with the database lock, and it now works.

I think there are a few fundamental flaws in the upgrade process here.

1. If these 2 records are not meant to be there on startup, then some script should delete them during the upgrade. Maybe one does and it didn't run properly, such as the thingworxPostgresSchemaUpdate7.4-to-8.0.bat file. If it is one of the other bat files in the update folder that should be run, then I missed it because I never saw it in the upgrade notes.

2. Why doesn't the startup process check to see if a record with those names exists first before attempting an insert? And if they do exist, delete them and then insert or simply do an update. That is fairly fundamental database methodology in my humble opinion.

3. Why isn't there a rollback on failure of the insert, rather than leaving the database locked and subsequently slowing down tomcat to effectively an inoperable state?

They would be 3 suggestions that I would offer to the Thingworx team, but I'm sure we are all guilty of missing safety nets in our code.

So thanks for your response Tony, and hopefully my notes here will help others.

Regards

Ben

[qngo]

Hi, there's also a similar error when I upgraded from TWX 7.1.x to 7.2.x with DB table "user_model_properties"

ERROR:  duplicate key value violates unique constraint "user_model_properties_pkey"

https://support.ptc.com/appserver/cs/view/solution.jsp?n=CS247876

[bmessenger]

Hi Quang-Dung Ngo,

I have effectively done exactly what that case says. By renaming the records it has had the same effect as deleting. Obviously, I didn't see that case when searching the support cases.

This error occurred when I upgraded from 7.3 to 8.0 on our dev machine. When I applied the same changes to our prod machine, I checked the table and records in question both before and after applying the Postgresql scripts. On prod the scripts removed the records. So I don;t know why the same scripts didn't remove the records on dev and they definitely did not report an error.

Thanks for the info and link. Should prove to be useful for others.

Cheers

Ben