Reading the Sharing Logs

Panorama X
1

I’m trying to help out on the forensics of a large data loss on a shared file. I’ve found what appears to be a significant clue in the sharing logs but can’t find anything definitive in how to read the logs. (There is an explanation in Help of the Log fields for Web Serving)

My take is that the “ts:” represents the number of records in the database when opened followed by the number after synching. My description below is based on that interpretation.

The highlighted record in the screenshot below fits the time when the problem began. It opened and synched with very different numbers. Subsequently other databases opening with the previous 795 records were all being dropped. Sessions 55, 7, and 8 were all the same user. Sessions 54, 5, 9, and 10 were by another user who experienced crashes on every attempt to open the file after the big change. Session 3 was a routine, automated opening and synch by Panorama. It was not unexpected that Sesson 3 opened with far fewer records, but it should have bumped up to the 795. Instead, it crashed. All of those with the 446 crashed.

Screenshot 2026-06-30 at 3.15.18 PM
Screenshot 2026-06-30 at 3.15.18 PM711×264 93 KB

What conditions would allow a database that was clearly “off”, to open and synchronize in this manner?

A bit earlier, the last synch by the user in Session 55 was:

Session 50 *** synchronized database: Distribution (ts:521-736 changed:95 deleted:11)

The numbers fit right in. The 644-840 do not. How the 446 seems to have worked its way in is also puzzling.

2

I’m trying to help out on the forensics of a large data loss on a shared file. I’ve found what appears to be a significant clue in the sharing logs

Let me start by saying that the sharing logs weren’t designed to be of any use for this sort of forensic purpose. I’m not sure what your goal is, but if you are somehow thinking that you can recover lost data from information in the logs, that isn’t something I would spend any time on myself.

These logs were primarily of use to me in debugging this code five years or so ago. But even five years ago when this was all fresh in my mind, I would mostly look at one of these synchronized log entries immediately after synchronization, to see if it matched what seemed to be happening. I don’t think I could ever have looked at a historical series of log entries and reverse engineered what had happened.

can’t find anything definitive in how to read the logs.

I’m pretty sure there is no written information about this, and as I said above, these logs weren’t really intended to contain enough information for the kind of forensic deep dive you are envisioning.

That said, I do have a vague recollection that I might have discussed these log entries when doing the video classes. I think this would most likely be in the Panorama X Server Deep Dive Part 4 video.

My take is that the “ts:” represents the number of records in the database

These numbers have nothing to do with the number of records. “ts” is short for “time stamp”. Panorama X time stamps aren’t actually based on clock time, but they do keep track of the order of events. So an event that happened at ts = 7 definitely occurred after an event at ts = 6. Every time any modification is made to a shared database, Panorama increments the internal time stamp.

If you take a new database and just add records to it, no other modifications, then the time stamp will correspond to the number of records. But usually other modifications are also happening - editing cells, deleting records, etc. So the time stamp can and does increase even if the number of records doesn’t go up - or even if it goes down.

Also, the time stamp will reset when a critical new generation is done. If your log isn’t recording new generations, you won’t see that in the log, but it could appear that time stamps are out of order.

followed by the number after synching

There are two numbers after “ts:” separated by a dash. Looking at the source code, I believe the first number is the time stamp when this client last requested a sync, in other words the client is telling the server “I am already synchronized up to this point”.

The second number is the time stamp the server has for this database. So the server will supply all of the changes between the client’s time stamp and the server’s. After the synchronization both the client and the server will have the same time stamp.

The highlighted record in the screenshot below fits the time when the problem began.

Ignore the first number, it’s the second number that is interesting. It went from 795 to 840 to 446. This number should NEVER go down, only up. The only exception would be if there was a new sharing generation. I don’t know if your logs are set up to record new sharing generations. I think you have to have Database Management checked under logging options. Based on the logs I would think there would have to have been TWO new sharing generations, one between 2:39 PM yesterday and 8:30 AM today, and another between 8:34 AM and 9:23 AM.

It’s interesting that the session numbers go from 55 to 3. Perhaps this means that the server restarted? Though if so, what happened to sessions 1, 2, 4 and 6? Hmm - this log is from THIS MORNING, so perhaps someone remembers whether the server restarted. Though restarting the server should not cause a synchronization problem, unless someone manually fiddled with the server files. Also, hopefully someone remembers whether any new sharing generations were done in the past 24 hours.

What are the settings for Auto Save Timeout and Save Transaction journal for this server? These control whether or not the server data is protected if the server crashes. Though they would have to be really wacky to cause log entries shown, I don’t think it would even be possible. But I have to ask.

3

I wasn‘t looking into the logs with any expectation of data recovery. The purpose was to see if I could determine when an error occurred, what user was involved, and any other clues that could help prevent whatever from happening again.

In the past, the logs have provided a lot of useful information in that regard.

I did look for any New Generations, and the last was some days earlier.

There was a restart when the web interface didn’t appear to be working right. I wasn’t involved and had no chance to review the exact status of Panorama, Panorama Server, or Abyss. That’s why the session numbers were reset. I’m very sure the individual involved would not have done anything with the server files, but I will check. On one side of the restart or the other, the crashing of this file began.

Not every user opens every file so those other sessions were using different files than the one in question. I imported the logs into a database and selected only the entries involving the file that was crashing and missing a couple of days worth of entries.

Auto Save is at 1. Save Transaction Journal was unchecked. I took the liberty to check it just now since that may have avoided the loss - assuming I understand its function.

All that said, we still don’t know what caused the issue and the missing data.

4

I imported the logs into a database and selected only the entries involving the file

Aha, it hadn’t occurred to me that only a subset of log entries were shown, but it makes perfect sense.

when the web interface

I guess we have to consider the possibility that a web procedure caused this. I don’t know of any way for a web procedure to cause a problem like this, in fact if I wanted to write a web procedure to cause such a problem I would be hard pressed to do so (actually come to think of it I could, but only with undocumented features that are used internally). But there isn’t any real way to put complete guardrails around web procedure code - that is code that is running directly on the server. Obviously I have no idea what your code does or how it is written, so I can’t really provide any direct advice on this. But you probably have an idea if there is any web procedure code that does anything unusual. You might want to consider adding logging to any web procedure code that does something complicated. Then if this happens again, you would have more detailed information to review.

5

The database with the lost days of records is shared but has no interface with the web at all. A couple of small, unshared databases handle all web interactions and are entirely separate, other than being handled by the same Panorama Server. I can’t see any reason that web actions would be involved in the sharing error here unless there’s some strange bug at work.

I continue to see the logs as a very useful tool in following up on issues and errors, and many times in the past they have served that purpose very well.

Per your observations, the 795 to 840 to 446 noted during synchronizing show where the loss likely occurred. We still don’t know how or why. Apparently, Session 55 or 3 was where it occurred. But would it likely be the local copy, or the server copy that made the 466 become the “official” ts? What could allow it to go from 840 to 446? That seems to be the main issue.

One more question about what the logs show…The highlighted record in my screenshot shows 520 changes. Are those changes that the synchronization made to the local copy? Similarly, would deletions then represent the number of records deleted by the synch?

6

Just received from the end user: “If I download data, it pulls in 10,624 records. Syncing it returns it to 7995. Should this not be the same? The lower number record count is mostly correct, as far as I can tell. The higher number is all duplicates. “

sync

Notice there are three different counts on the visible records, and two different values on the Total. What’s right?

He used Check Synchronization and got an immense list; 370KB.

He’s going to unshare, clean it up, and reshare. But obviously he’s disturbed by these inexplicable errors.

7

the 795 to 840 to 446 noted during synchronizing

An important distinction - these changes did not happen during synchronization.

In Panorama X, Synchronization does not modify the server database AT ALL. The client sends a request to the server saying “I was last synchronized at a time stamp of NN, please send me a copy of all database changes that have been made since NN”. The server collects all of the changes during the requested period, packages them up, and sends them back to the client. Then these changes are applied to the local client copy of the database. But the server copy of the database does not change in any way. This includes the time stamp on the server - synchronization doesn’t change that number.

Whenever any change is made on a client, the change is immediately sent to the server. The server copy of the database is updated with the change, and the time stamp is incremented. So the time stamp can only go up, and only by one number at a time. In your log the number appears to jump from 795 to 840 between 2:39 PM and 8:33 AM the next day, but that’s because 45 changes were made but no one synchronized during that period.

Based on the logs I would think there would have to have been TWO new sharing generations

I misread the log entries yesterday, there is only one spot where something unusual happened, between 8:34 AM and 9:23 AM. Somehow the time stamp went DOWN during this period, from 840 to 446. Also, apparently the server was stopped and restarted during this period.

The only scenario that I can imagine that would cause this would be:

  1. The server is shut down
  2. The copy of the database file on the server is manually replaced with an older copy of the file, for example someone restored a backup.
  3. The server is restarted, and the older copy of the file is loaded into memory.

Of course step 2 is pretty wild, but this would perfectly explain the log entries. The problem definitely occurred in the period where Panorama X Server.app was relaunched.

Yesterday I hypothesized about someone doing a new sharing generation, but that would not produce this sequence in the log. If a New Sharing Generation had been done, the time stamp would have gone from 840 to 1 (or possibly 0).

So I think the ONLY possible explanation is that somehow this database file was replaced with an older version of the file, and then the server was restarted. Once that happened, of course synchronization won’t work any more - the logs show that most of the clients had newer copies of the database than the server has. The synchronization code relies on the fact that the server is always newer or at least the same time stamp as all clients.

The first entry after the restart (9:23 AM) is interesting - this client also has the 446 time stamp. I believe that the server copy was already replaced, and then this client downloaded the database for the first time, so it got the out of date copy. It then immediately synchronized (this is normal), which is what we see in the log.

The numbers fit right in. The 644-840 do not.

No, this number is fine. The 840 is the time stamp on the server, which fits right in with the previous sequence of time stamps. The 644 simply means that that particular client hadn’t been synchronized for a while. At that point in time, any value from 0 to 840 would be valid for the time stamp on a client computer. A value of 0 would simply indicate that that client had never synchronized since the most recent new generation. Perhaps unlikely, but definitely possible (for example you could have made a copy after the new generation, and never touched that copy).

How the 446 seems to have worked its way in is also puzzling.

Yes, this is the key number, as I explained above.

unless there’s some strange

There is definitely something strange going on. At this point, I believe that somehow a database file has been swapped out behind Panorama’s back.

He’s going to unshare, clean it up, and reshare.

Was that not done immediately on the 30th?

If I download data, it pulls in 10,624 records. Syncing it returns it to 7995. Should this not be the same?

Of course it should be the same as long as everything is working fine. The only reason there is a Download Data command is for a case where everything his not working fine.

The Panorama X server system is designed such that the server always contains the correct, most up-to-date data. So normally using Download Data will insure that the client you downloaded to will now also contain the correct, most up-to-date data. Synchronizing should also accomplish this, but if the time stamps on the client got out of whack, it wouldn’t. This was particularly an issue during the Panorama X Server beta period. There haven’t been any “time stamp out of whack” issues reported in a while, so Download Data shouldn’t be necessary.

But if a database file on the server is changed behind Panorama’s back, all bets are off. Now the copy on the server is no longer the correct, most up-to-date version of the database. There is really nothing that Panorama’s code could do about something like this. Essentially Panorama has been sabotaged, perhaps not the best choice of words since I’m sure this wasn’t intentional, but the effect is the same.

At this point I would find the client copy that is the most recent, and use that to re-upload the database to the server. You can check the time stamp of a database by using the info(“serverrecordts”) function, you want the highest number. I would recommend disabling server connections on the client so that it doesn’t try to synchronize, which can be done in the Preferences>Client panel.

image

  1. Disable Server Connections
  2. Open database
  3. Check time stamp #

Once you’ve found the client with the highest time stamp, disconnect it from the server, then turn server connections back on and upload to the server.

8

Their Canadian holiday opened a window of opportunity for analysis before reaction.