2 projects in dev gateway deleted mysteriously

nminchin · August 24, 2022, 6:53am

8.1.18

2 of my projects in my dev environment just up and vanished, poof. Not sure what happened… The Perspective Client I was running all of a sudden just said “Project not found” or something. By disappeared, I mean they were no longer in the Projects section under the gw webpage and all of the files were missing on the server under the filesystem.

LUCKILY and perhaps suspiciously, I had a colleague collect a backup literally seconds before the projects disappeared and I was able to restore it and resume from where I left off.

I saw this suspicious entry in the wrapper log below. Note: the ‘global’ and ‘alarm-pipline’ projects are the ones to vanish.

INFO   | jvm 1    | 2022/08/24 14:45:06 | I [c.i.i.g.u.BackupRestoreDelegate] [05:15:06]: Starting restore procedure, writing upload to disk... 
INFO   | jvm 1    | 2022/08/24 14:45:11 | W [c.i.i.g.u.BackupRestoreDelegate] [05:15:11]: Restore failed: Failed to delete the data/projects directory. This may result in incorrect project overwrites and merges 
INFO   | jvm 1    | 2022/08/24 14:45:11 | com.inductiveautomation.ignition.gateway.util.BackupRestoreDelegate$ProjectBackupException: Failed to delete the data/projects directory. This may result in incorrect project overwrites and merges
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at com.inductiveautomation.ignition.gateway.util.BackupRestoreDelegate.backupProjectData(BackupRestoreDelegate.java:590)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at com.inductiveautomation.ignition.gateway.util.BackupRestoreDelegate.restore(BackupRestoreDelegate.java:229)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at com.inductiveautomation.ignition.gateway.web.pages.config.RestorePanel.onFormSubmit(RestorePanel.java:161)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at com.inductiveautomation.ignition.gateway.web.pages.config.RestorePanel$1.onSubmitInternal(RestorePanel.java:55)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at com.inductiveautomation.ignition.gateway.web.components.CsrfPreventingForm.onSubmit(CsrfPreventingForm.java:67)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.apache.wicket.markup.html.form.Form.delegateSubmit(Form.java:1310)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.apache.wicket.markup.html.form.Form.process(Form.java:967)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.apache.wicket.markup.html.form.Form.onFormSubmitted(Form.java:789)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.apache.wicket.markup.html.form.Form.onFormSubmitted(Form.java:701)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at jdk.internal.reflect.GeneratedMethodAccessor218.invoke(Unknown Source)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at java.base/java.lang.reflect.Method.invoke(Unknown Source)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.apache.wicket.RequestListenerInterface.internalInvoke(RequestListenerInterface.java:258)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.apache.wicket.RequestListenerInterface.invoke(RequestListenerInterface.java:216)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.apache.wicket.core.request.handler.ListenerInterfaceRequestHandler.invokeListener(ListenerInterfaceRequestHandler.java:243)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.apache.wicket.core.request.handler.ListenerInterfaceRequestHandler.respond(ListenerInterfaceRequestHandler.java:236)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.apache.wicket.request.cycle.RequestCycle$HandlerExecutor.respond(RequestCycle.java:890)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.apache.wicket.request.RequestHandlerStack.execute(RequestHandlerStack.java:64)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.apache.wicket.request.cycle.RequestCycle.execute(RequestCycle.java:261)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.apache.wicket.request.cycle.RequestCycle.processRequest(RequestCycle.java:218)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.apache.wicket.request.cycle.RequestCycle.processRequestAndDetach(RequestCycle.java:289)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.apache.wicket.protocol.http.WicketFilter.processRequestCycle(WicketFilter.java:259)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.apache.wicket.protocol.http.WicketFilter.processRequest(WicketFilter.java:201)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.apache.wicket.protocol.http.WicketFilter.doFilter(WicketFilter.java:282)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:201)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:548)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:600)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1440)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:501)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1355)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at com.inductiveautomation.catapult.handlers.RemoteHostNameLookupHandler.handle(RemoteHostNameLookupHandler.java:121)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.rewrite.handler.RewriteHandler.handle(RewriteHandler.java:322)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:59)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.server.Server.handle(Server.java:516)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:487)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:732)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:479)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034)
INFO   | jvm 1    | 2022/08/24 14:45:11 | 	at java.base/java.lang.Thread.run(Unknown Source)

Then I see this

INFO   | jvm 1    | 2022/08/24 14:48:48 | I [s.ProjectRunner               ] [05:18:48]: Project shutdown. project-name=alarm-pipelines
INFO   | jvm 1    | 2022/08/24 14:48:48 | I [a.N.Pipeline                  ] [05:18:48]: [name=Email,version=1660653611858] Alarm pipeline scheduled to retire. alarm-pipeline=project:alarm-pipelines:/pipeline:Email
INFO   | jvm 1    | 2022/08/24 14:48:48 | I [a.N.Pipeline                  ] [05:18:48]: [name=SMS - Test,version=1660653611861] Alarm pipeline scheduled to retire. alarm-pipeline=project:alarm-pipelines:/pipeline:SMS - Test
INFO   | jvm 1    | 2022/08/24 14:48:48 | I [a.N.Pipeline                  ] [05:18:48]: [name=Email,version=1660653611858] Alarm pipeline retired. 
INFO   | jvm 1    | 2022/08/24 14:48:48 | I [a.N.Pipeline                  ] [05:18:48]: [name=SMS - Test,version=1660653611861] Alarm pipeline retired. 
INFO   | jvm 1    | 2022/08/24 14:48:48 | I [c.i.i.g.p.IgnitionProjectManager$ProjectScriptLifecycleFactory] [05:18:48]: Hierarchy change; shutting down lifecycle for 'TWE_Wynns' project-name=global
INFO   | jvm 1    | 2022/08/24 14:48:48 | I [c.i.i.g.p.IgnitionProjectManager$ProjectAuditLifecycleFactory] [05:18:48]: Hierarchy change; shutting down lifecycle for 'TWE_Wynns' project-name=global
INFO   | jvm 1    | 2022/08/24 14:48:48 | I [GatewayNamedQueryManager      ] [05:18:48]: Named Query Executor not found for project 'global' project-name=TWE_Wynns, view=Header_BPL@T[0]$0:0
INFO   | jvm 1    | 2022/08/24 14:48:48 | I [c.i.i.g.d.n.GatewayNamedQueryManager$NamedQueryLifecycleFactory] [05:18:48]: Hierarchy change; shutting down lifecycle for 'TWE_Wynns' project-name=global
INFO   | jvm 1    | 2022/08/24 14:48:48 | I [c.i.s.ChartManager$ChartCompilerLifecycleFactory] [05:18:48]: Hierarchy change; shutting down lifecycle for 'TWE_Wynns' project-name=global
INFO   | jvm 1    | 2022/08/24 14:48:48 | I [s.ProjectRunner               ] [05:18:48]: Project shutdown. project-name=global
INFO   | jvm 1    | 2022/08/24 14:48:48 | I [c.i.f.FactorySQLGatewayHook$SqlBridgeProjectLifecycleFactory] [05:18:48]: Hierarchy change; shutting down lifecycle for 'TWE_Wynns' 
INFO   | jvm 1    | 2022/08/24 14:48:48 | I [s.ProjectRunner               ] [05:18:48]: Project shutdown. project-name=TWE_Wynns
INFO   | jvm 1    | 2022/08/24 14:48:48 | I [c.i.p.g.c.PerspectiveProjectCacheImpl$PerspectiveProjectLifecycleFactory] [05:18:48]: Hierarchy change; shutting down lifecycle for 'TWE_Wynns'

followed by a bazillion of these below for different views and props

Error shutting down binding "tag on props.text" project-name=TWE_Wynns, view=Shared/_Templates/Devices/Pump_01b@C$0:26, component=root/CoordinateContainer/speed_text

Any ideas??

victordcq · August 24, 2022, 9:07am

yeah i think these events are going to be related

Kevin.Herron · August 24, 2022, 11:26am

I think you had a colleague accidentally restore a backup as well, which seems to have failed for some reason.

PGriffith · August 24, 2022, 3:41pm

nminchin:

com.inductiveautomation.ignition.gateway.util.BackupRestoreDelegate$ProjectBackupException: Failed to delete the data/projects directory. This may result in incorrect project overwrites and merges
	at com.inductiveautomation.ignition.gateway.util.BackupRestoreDelegate.backupProjectData(BackupRestoreDelegate.java:590)
	at com.inductiveautomation.ignition.gateway.util.BackupRestoreDelegate.restore(BackupRestoreDelegate.java:229)
	at com.inductiveautomation.ignition.gateway.web.pages.config.RestorePanel.onFormSubmit(RestorePanel.java:161)
	at com.inductiveautomation.ignition.gateway.web.pages.config.RestorePanel$1.onSubmitInternal(RestorePanel.java:55)
	at com.inductiveautomation.ignition.gateway.web.components.CsrfPreventingForm.onSubmit(CsrfPreventingForm.java:67)
	at org.apache.wicket.markup.html.form.Form.delegateSubmit(Form.java:1310)
	at org.apache.wicket.markup.html.form.Form.process(Form.java:967)
	at org.apache.wicket.markup.html.form.Form.onFormSubmitted(Form.java:789)
	at org.apache.wicket.markup.html.form.Form.onFormSubmitted(Form.java:701)
	at jdk.internal.reflect.GeneratedMethodAccessor218.invoke(Unknown Source)

Yeah, that stacktrace is pretty damning evidence. Someone clicked the 'restore' button.

nminchin · August 24, 2022, 8:40pm

This is what I suspected as well, but I can’t imagine that he would have tried to restore an actual backup. What happens when you press restore without selecting a backup file first?

PGriffith · August 24, 2022, 8:49pm

You get a ‘you must choose a .gwbk’ warning:

nminchin · August 24, 2022, 8:53pm

I thought that was the case but didn’t want to press it myself just in case and in that case I have no idea how he did it… I can’t imagine why he would take a backup and then try to restore it… oh well, at least I didn’t lose anything!!