search

Dynalon / Rainy

Simple Tomboy/Tomdroid cloud/syncing server. Written in C# with AngularJS web frontend. Supports SQLite & Postgres Backends.
http://dynalon.github.io/Rainy
GNU Affero General Public License v3.0
88 stars 15 forks source link

Synchronization failed with the following exception: Invalid syntax: Unterminated string, expected '"' termination, got 'a' at [1:4097] #24

Closed luisca closed 10 years ago

luisca commented 10 years ago

Just installed Rainy v0.5.0, it was working for a day and now I am getting the following error on sync:

[ERROR 12:03:58.695] Synchronization failed with the following exception: Invalid syntax: Unterminated string, expected '"' termination, got 'a' at [1:4097] at Hyena.Json.Tokenizer.InvalidSyntax (System.String message) [0x00000] in :0 at Hyena.Json.Tokenizer.LexString () [0x00000] in :0 at Hyena.Json.Tokenizer.InnerScan () [0x00000] in :0 at Hyena.Json.Tokenizer.Scan () [0x00000] in :0 at Hyena.Json.Deserializer.CheckScan (TokenType expected, Boolean eofok) [0x00000] in :0 at Hyena.Json.Deserializer.CheckScan (TokenType expected) [0x00000] in :0 at Hyena.Json.Deserializer.ParseObject () [0x00000] in :0 at Hyena.Json.Deserializer.Parse (Hyena.Json.Token token) [0x00000] in :0 at Hyena.Json.Deserializer.ParseArray () [0x00000] in :0 at Hyena.Json.Deserializer.ParseObject () [0x00000] in :0 at Hyena.Json.Deserializer.Parse (Hyena.Json.Token token) [0x00000] in :0 at Hyena.Json.Deserializer.Deserialize () [0x00000] in :0 at Tomboy.WebSync.Api.UserInfo.ParseJsonNotes (System.String jsonString, System.Nullable1& latestSyncRevision) [0x00000] in <filename unknown>:0 at Tomboy.WebSync.Api.UserInfo.GetNotes (Boolean includeContent, Int32 sinceRevision, System.Nullable1& latestSyncRevision) [0x00000] in :0 at Tomboy.WebSync.WebSyncServer.GetNoteUpdatesSince (Int32 revision) [0x00000] in :0 at Tomboy.Sync.SyncManager.SynchronizationThread () [0x00000] in :0

(Tomboy:25874): GLib-CRITICAL **: g_source_remove: assertion `tag > 0' failed

I was also getting this error and a different computer but after a while the sync did work.

Dynalon commented 10 years ago

Can you please try to reproduce that error and attach the Rainy logging output (remove user credentials if necessary), that would help me tackle this.

luisca commented 10 years ago

It worked after a few retrials, maybe it is some kind of timeout issue? I'll try to get that information if I manage to reproduce it. Thanks!

luisca commented 10 years ago

Ok, running into trouble again. I can update from a computer (where I have made no changes). From another computer, where I have made changes, it connects, it shows it is updating/adding all the correct notes, but I the end I get "Could not synchronize notes", and indeed if I try again same result (it shows it updating the same notes again, which means the update did not go through). I am trying to attach tomboy and rainy logs, but this doesn't let me attach a txt file. email?

I see "committing changes" on the UI for a second before it failing.

luisca commented 10 years ago

By the way, I'm noticing when I create new notes on tomboy (select text + Ctrl+L), the tile of the text always is "New Note Template-deactivate", even though the selected text takes you correctly to the note.

luisca commented 10 years ago

Looks like I fixed that issue by removing a bunch of notes (the new note-deactivate) but the problem still happens. Let me know if you need any more information!

luisca commented 10 years ago

Anyway, here is the tomboy output:

[INFO 14:19:44.980] Initializing Mono.Addins [ERROR 14:19:56.081] Caught exception. Message: Error: ConnectFailure (Connection refused) [ERROR 14:19:56.085] Stack trace for previous exception: at System.Net.HttpWebRequest.EndGetResponse (IAsyncResult asyncResult) [0x00000] in :0 at System.Net.HttpWebRequest.GetResponse () [0x00000] in :0 at Tomboy.WebSync.Api.OAuth.MakeWebRequest (RequestMethod method, System.String url, System.Collections.Generic.List1 parameters, System.String postData) [0x00000] in <filename unknown>:0 [ERROR 14:19:56.087] Rest of stack trace for above exception: at System.Environment.get_StackTrace() at Tomboy.WebSync.Api.OAuth.MakeWebRequest(RequestMethod method, System.String url, System.Collections.Generic.List1 parameters, System.String postData) at Tomboy.WebSync.Api.OAuth.WebRequest(RequestMethod method, System.String url, System.String postData) at Tomboy.WebSync.Api.OAuth.Get(System.String uri, IDictionary2 queryParameters) at Tomboy.WebSync.Api.RootInfo.GetRoot(System.String rootUri, IWebConnection connection) at Tomboy.WebSync.WebSyncServer.BeginSyncTransaction() at Tomboy.Sync.SyncManager.SynchronizationThread() at System.Threading.Thread.StartInternal() [ERROR 14:19:56.087] Synchronization failed with the following exception: Error: ConnectFailure (Connection refused) at System.Net.HttpWebRequest.EndGetResponse (IAsyncResult asyncResult) [0x00000] in <filename unknown>:0 at System.Net.HttpWebRequest.GetResponse () [0x00000] in <filename unknown>:0 at Tomboy.WebSync.Api.OAuth.MakeWebRequest (RequestMethod method, System.String url, System.Collections.Generic.List1 parameters, System.String postData) [0x00000] in :0

(Tomboy:15210): GLib-CRITICAL **: g_source_remove: assertion tag > 0' failed [ERROR 14:21:00.764] Caught exception. Message: The remote server returned an error: (500) Internal server error.. [ERROR 14:21:00.765] Stack trace for previous exception: at System.Net.HttpWebRequest.CheckFinalStatus (System.Net.WebAsyncResult result) [0x00000] in <filename unknown>:0 at System.Net.HttpWebRequest.SetResponseData (System.Net.WebConnectionData data) [0x00000] in <filename unknown>:0 [ERROR 14:21:00.765] Rest of stack trace for above exception: at System.Environment.get_StackTrace() at Tomboy.WebSync.Api.OAuth.MakeWebRequest(RequestMethod method, System.String url, System.Collections.Generic.List1 parameters, System.String postData) at Tomboy.WebSync.Api.OAuth.WebRequest(RequestMethod method, System.String url, System.String postData) at Tomboy.WebSync.Api.OAuth.Put(System.String uri, IDictionary2 queryParameters, System.String putValue) at Tomboy.WebSync.Api.UserInfo.UpdateNotes(IList1 noteUpdates, Int32 expectedNewRevision) at Tomboy.WebSync.WebSyncServer.CommitSyncTransaction() at Tomboy.Sync.SyncManager.SynchronizationThread() at System.Threading.Thread.StartInternal() [ERROR 14:21:00.765] Synchronization failed with the following exception: The remote server returned an error: (500) Internal server error.. at System.Net.HttpWebRequest.CheckFinalStatus (System.Net.WebAsyncResult result) [0x00000] in :0 at System.Net.HttpWebRequest.SetResponseData (System.Net.WebConnectionData data) [0x00000] in :0

(Tomboy:15210): GLib-CRITICAL **: g_source_remove: assertion `tag > 0' failed

luisca commented 10 years ago

And here is the rainy log:

[a lot of actual content of notes] 13/10/17_21:21:00.102 [DEBUG] Rainy.WebService.NotesService->Put - client sent LatestSyncRevision: 48 13/10/17_21:21:00.642 [DEBUG] Rainy.WebService.NotesService->Put - CAUGHT EXCEPTION: Abort due to constraint violation column CompoundPrimaryKey is not unique at Mono.Data.Sqlite.SQLite3.Reset (Mono.Data.Sqlite.SqliteStatement stmt) [0x00000] in :0 at Mono.Data.Sqlite.SQLite3.Step (Mono.Data.Sqlite.SqliteStatement stmt) [0x00000] in :0 at Mono.Data.Sqlite.SqliteDataReader.NextResult () [0x00000] in :0 at (wrapper remoting-invoke-with-check) Mono.Data.Sqlite.SqliteDataReader:NextResult () at Mono.Data.Sqlite.SqliteDataReader..ctor (Mono.Data.Sqlite.SqliteCommand cmd, CommandBehavior behave) [0x00000] in :0 at (wrapper remoting-invoke-with-check) Mono.Data.Sqlite.SqliteDataReader:.ctor (Mono.Data.Sqlite.SqliteCommand,System.Data.CommandBehavior) at Mono.Data.Sqlite.SqliteCommand.ExecuteReader (CommandBehavior behavior) [0x00000] in :0 at Mono.Data.Sqlite.SqliteCommand.ExecuteNonQuery () [0x00000] in :0 at ServiceStack.OrmLite.OrmLiteWriteExtensions.ExecuteSql (IDbCommand dbCmd, System.String sql) [0x00000] in :0 at ServiceStack.OrmLite.OrmLiteWriteExtensions.Insert[DBArchivedNote](IDbCommand dbCmd, Rainy.Db.DBArchivedNote[] objs) [0x00000] in :0 at ServiceStack.OrmLite.OrmLiteWriteConnectionExtensions+<>cDisplayClass48`1[Rainy.Db.DBArchivedNote].b47 (IDbCommand dbCmd) [0x00000] in <filename unknown

:0 at ServiceStack.OrmLite.ReadConnectionExtensions.Exec (IDbConnection dbConn, System.Action1 filter) [0x00000] in <filename unknown>:0 at ServiceStack.OrmLite.OrmLiteWriteConnectionExtensions.Insert[DBArchivedNote] (IDbConnection dbConn, Rainy.Db.DBArchivedNote[] objs) [0x00000] in <filename unknown>: 0 at Rainy.Db.DbStorage.SaveDBNote (Rainy.Db.DBNote db_note) [0x00000] in <filename unknown>:0 at Rainy.Db.DbEncryptedStorage.SaveNote (Tomboy.Note note) [0x00000] in <filename unknown>:0 at Tomboy.Engine.SaveNote (Tomboy.Note note, Boolean update_dates) [0x00000] in <filename unknown>:0 at Rainy.WebService.NotesService.Put (Rainy.WebService.PutNotesRequest request) [0x00000] in <filename unknown>:0 13/10/17_21:21:00.689 [DEBUG] Rainy.ErrorHandling.ExceptionHandler->HandleException - Abort due to constraint violation column CompoundPrimaryKey is not unique 13/10/17_21:21:00.702 [DEBUG] Rainy.ErrorHandling.ExceptionHandler->LogExceptionDetails - at Mono.Data.Sqlite.SQLite3.Reset (Mono.Data.Sqlite.SqliteStatement stmt) [0x 00000] in <filename unknown>:0 at Mono.Data.Sqlite.SQLite3.Step (Mono.Data.Sqlite.SqliteStatement stmt) [0x00000] in <filename unknown>:0 at Mono.Data.Sqlite.SqliteDataReader.NextResult () [0x00000] in <filename unknown>:0 at (wrapper remoting-invoke-with-check) Mono.Data.Sqlite.SqliteDataReader:NextResult () at Mono.Data.Sqlite.SqliteDataReader..ctor (Mono.Data.Sqlite.SqliteCommand cmd, CommandBehavior behave) [0x00000] in <filename unknown>:0 at (wrapper remoting-invoke-with-check) Mono.Data.Sqlite.SqliteDataReader:.ctor (Mono.Data.Sqlite.SqliteCommand,System.Data.CommandBehavior) at Mono.Data.Sqlite.SqliteCommand.ExecuteReader (CommandBehavior behavior) [0x00000] in <filename unknown>:0 at Mono.Data.Sqlite.SqliteCommand.ExecuteNonQuery () [0x00000] in <filename unknown>:0 at ServiceStack.OrmLite.OrmLiteWriteExtensions.ExecuteSql (IDbCommand dbCmd, System.String sql) [0x00000] in <filename unknown>:0 at ServiceStack.OrmLite.OrmLiteWriteExtensions.Insert[DBArchivedNote] (IDbCommand dbCmd, Rainy.Db.DBArchivedNote[] objs) [0x00000] in <filename unknown>:0 at ServiceStack.OrmLite.OrmLiteWriteConnectionExtensions+<>c__DisplayClass481[Rainy.Db.DBArchivedNote].b__47 (IDbCommand dbCmd) [0x00000] in <filename unknown :0 at ServiceStack.OrmLite.ReadConnectionExtensions.Exec (IDbConnection dbConn, System.Action`1 filter) [0x00000] in :0 at ServiceStack.OrmLite.OrmLiteWriteConnectionExtensions.Insert[DBArchivedNote](IDbConnection dbConn, Rainy.Db.DBArchivedNote[] objs) [0x00000] in : 0 at Rainy.Db.DbStorage.SaveDBNote (Rainy.Db.DBNote db_note) [0x00000] in :0 at Rainy.Db.DbEncryptedStorage.SaveNote (Tomboy.Note note) [0x00000] in :0 at Tomboy.Engine.SaveNote (Tomboy.Note note, Boolean update_dates) [0x00000] in :0 at Rainy.WebService.NotesService.Put (Rainy.WebService.PutNotesRequest request) [0x00000] in :0

Dynalon commented 10 years ago

Out of this all log files, I can pinpoint the error down to Abort due to constraint violation column CompoundPrimaryKey is not unique. This happens if you try to upload a note with the same GUID twice. This does not work, because the Guid is part of the primary key in the database.

With Rainy versions 0.2.X this could happen if two different users uplaod the same notes. Starting from version 0.5.0 this is fixed, so multiple users can have same GUIDs. If you are on 0.2.x please upgrade, if you are on 0.5.0 we need to find out how there may be two tomboy notes with same GUID. I have never encountered "note-deactivate" in Tomboy, what tomboy version are you on? If it creates note copies without changing the GUID, this is just wrong.

luisca commented 10 years ago

I am on 0.5.0. I use tomboy 1.10.1.

After playing around with template notes (deleting them and trying to re-sync, they are regenerated after a bit), I was able to sync both computers. It looks like this morning I am seeing a different error, rainy log (edited out details)

13/10/18_15:00:53.964 [DEBUG] Rainy.WebService.RequestLogFilterAttribute->RequestFilter - Received request at: /api/1.0/myusername Deserialized data (JSV): { Username: myusername } 13/10/18_15:00:53.981 [DEBUG] Rainy.WebService.RequestLogFilterAttribute->RequestFilter - Received request headers:

13/10/18_15:00:53.995 [DEBUG] Rainy.WebService.RequestLogFilterAttribute->RequestFilter - Authorization: OAuth realm="Snowy",oauth_consumer_key="anyone",oauth_nonce="XXX",oauth_signature="XXXXX",oauth_signature_method="HMAC-SHA1",oauth_timestamp="XXX",oauth_token="XXX",oauth_version="1.0" 13/10/18_15:00:54.008 [DEBUG] Rainy.WebService.RequestLogFilterAttribute->RequestFilter - Host: myhostname:8080 13/10/18_15:00:54.067 [DEBUG] Rainy.WebService.OAuth.OAuthRequiredAttribute->RequestFilter - trying to acquire authorization 13/10/18_15:00:56.256 [DEBUG] Rainy.ErrorHandling.ExceptionHandler->HandleException - Cannot cast from source type to destination type. 13/10/18_15:00:56.278 [DEBUG] Rainy.ErrorHandling.ExceptionHandler->LogExceptionDetails - at System.Collections.Specialized.NameValueCollection.AsSingleString (System.Collections.ArrayList) <0x00094> at System.Collections.Specialized.NameValueCollection.Get (string) <0x0005b> at System.Collections.Specialized.NameValueCollection.get_Item (string) <0x00027> at DevDefined.OAuth.Framework.BoundParameter.get_Value () <0x0002b> at DevDefined.OAuth.Framework.OAuthContext.get_Timestamp () <0x0001f> at (wrapper dynamic-method) object.lambda_method (System.Runtime.CompilerServices.Closure,DevDefined.OAuth.Framework.OAuthContext) <0x00027> at ServiceStack.Text.Common.WriteType`2<DevDefined.OAuth.Framework.OAuthContext, ServiceStack.Text.Jsv.JsvTypeSerializer>.WriteProperties (System.IO.TextWriter,object) <0x0025f> at ServiceStack.Text.TypeSerializer.SerializeToString (object,System.Type) <0x0011b> at ServiceStack.Text.TypeSerializer.SerializeToString (DevDefined.OAuth.Framework.IOAuthContext) <0x0016f> at ServiceStack.Text.TypeSerializer.SerializeAndFormat (DevDefined.OAuth.Framework.IOAuthContext) <0x0007b> at ServiceStack.Text.TypeSerializer.Dump (DevDefined.OAuth.Framework.IOAuthContext) <0x00023> at Rainy.WebService.OAuth.OAuthRequiredAttribute.RequestFilter (ServiceStack.ServiceHost.IHttpRequest,ServiceStack.ServiceHost.IHttpResponse,object) <0x0076b> at ServiceStack.WebHost.Endpoints.EndpointHost.ApplyRequestFilters (ServiceStack.ServiceHost.IHttpRequest,ServiceStack.ServiceHost.IHttpResponse,object) <0x0034b> at ServiceStack.WebHost.Endpoints.RestHandler.ProcessRequest (ServiceStack.ServiceHost.IHttpRequest,ServiceStack.ServiceHost.IHttpResponse,string) <0x0026f>

luisca commented 10 years ago

Looks like I am hitting the original bug again:

From rainy it's all notes content, I don't see any error.

from tomboy: [ERROR 13:09:44.195] Synchronization failed with the following exception: Invalid syntax: Unterminated string, expected '"' termination, got ')' at [1:422913] at Hyena.Json.Tokenizer.InvalidSyntax (System.String message) [0x00000] in :0 at Hyena.Json.Tokenizer.LexString () [0x00000] in :0 at Hyena.Json.Tokenizer.InnerScan () [0x00000] in :0 at Hyena.Json.Tokenizer.Scan () [0x00000] in :0 at Hyena.Json.Deserializer.CheckScan (TokenType expected, Boolean eofok) [0x00000] in :0 at Hyena.Json.Deserializer.CheckScan (TokenType expected) [0x00000] in :0 at Hyena.Json.Deserializer.ParseObject () [0x00000] in :0 at Hyena.Json.Deserializer.Parse (Hyena.Json.Token token) [0x00000] in :0 at Hyena.Json.Deserializer.ParseArray () [0x00000] in :0 at Hyena.Json.Deserializer.ParseObject () [0x00000] in :0 at Hyena.Json.Deserializer.Parse (Hyena.Json.Token token) [0x00000] in :0 at Hyena.Json.Deserializer.Deserialize () [0x00000] in :0 at Tomboy.WebSync.Api.UserInfo.ParseJsonNotes (System.String jsonString, System.Nullable1& latestSyncRevision) [0x00000] in <filename unknown>:0 at Tomboy.WebSync.Api.UserInfo.GetNotes (Boolean includeContent, Int32 sinceRevision, System.Nullable1& latestSyncRevision) [0x00000] in :0 at Tomboy.WebSync.Api.UserInfo.GetNotes (Boolean includeContent, System.Nullable`1& latestSyncRevision) [0x00000] in :0 at Tomboy.WebSync.WebSyncServer.GetAllNoteUUIDs () [0x00000] in :0 at Tomboy.Sync.SyncManager+cAnonStorey13.<>m40 () [0x00000] in :0 at Tomboy.GuiUtils+cAnonStoreyC.<>m2F (System.Object , System.EventArgs ) [0x00000] in :0

(Tomboy:18717): GLib-CRITICAL **: g_source_remove: assertion tag > 0' failed [ERROR 13:10:39.607] Synchronization failed with the following exception: Invalid syntax: Unterminated string, expected '"' termination, got 'i' at [1:10241] at Hyena.Json.Tokenizer.InvalidSyntax (System.String message) [0x00000] in <filename unknown>:0 at Hyena.Json.Tokenizer.LexString () [0x00000] in <filename unknown>:0 at Hyena.Json.Tokenizer.InnerScan () [0x00000] in <filename unknown>:0 at Hyena.Json.Tokenizer.Scan () [0x00000] in <filename unknown>:0 at Hyena.Json.Deserializer.CheckScan (TokenType expected, Boolean eofok) [0x00000] in <filename unknown>:0 at Hyena.Json.Deserializer.CheckScan (TokenType expected) [0x00000] in <filename unknown>:0 at Hyena.Json.Deserializer.ParseObject () [0x00000] in <filename unknown>:0 at Hyena.Json.Deserializer.Parse (Hyena.Json.Token token) [0x00000] in <filename unknown>:0 at Hyena.Json.Deserializer.ParseArray () [0x00000] in <filename unknown>:0 at Hyena.Json.Deserializer.ParseObject () [0x00000] in <filename unknown>:0 at Hyena.Json.Deserializer.Parse (Hyena.Json.Token token) [0x00000] in <filename unknown>:0 at Hyena.Json.Deserializer.Deserialize () [0x00000] in <filename unknown>:0 at Tomboy.WebSync.Api.UserInfo.ParseJsonNotes (System.String jsonString, System.Nullable1& latestSyncRevision) [0x00000] in :0 at Tomboy.WebSync.Api.UserInfo.GetNotes (Boolean includeContent, Int32 sinceRevision, System.Nullable`1& latestSyncRevision) [0x00000] in :0 at Tomboy.WebSync.WebSyncServer.GetNoteUpdatesSince (Int32 revision) [0x00000] in :0 at Tomboy.Sync.SyncManager.SynchronizationThread () [0x00000] in :0

j-4 commented 10 years ago

I get the same problem with your testserver: https://gist.github.com/j-4/b52dedb8afbef0234165

can't sync from any device any more :-( You should have the logs!

j-4 commented 10 years ago

Same error without any notes. Can't even delete remote notes using Tomdroids option. Seems something is wrong on the server-side...

Dynalon commented 10 years ago

Is this ony happening with the testserver, or does this apply to local 0.5.0 installations as well? Test server is running on latest git, with quite some changes from the hackfest

Dynalon commented 10 years ago

Luckily I could reproduce this by coincidence and spend hours debugging tomboy. Tomboy's HTTP transport has trouble with chunked http encodings, but only sometimes. I suspect it happens when some bytes in the note content are alignd to the end of the chunked buffer and Tomboy then interprets it as end-of-sequence character. But that is only a suspicion, could be sth. different.

Anyways, the commit added a fix that will prevent chunked encoding on the Server and should fix this. I am documenting this here, as as soon as you use an nginx proxy or apache mod_mono, this might re-introduce the bug so one has to deactivate chunked transfer there too.