We experienced an extremely concerning synchronisation issue that we need to get to the bottom of.
Our setup consists of a linux box hosting the rhoconnect services talking to our Windows server (hosts an SQL database) over WebAPI calls.
A user in the field reported that they could not see the jobs that had been sent to them on their Android device.
On examination of the SQL server, the job data they expected could be seen.
On examination of the rhoconnect data through the console web interface, the job data they expected could be seen.
The device had a valid connection.
Further data (of a different class) could be sent to the device to prove that it was not a connectivity issue (i.e. a message class we have available).
When job data arrives on the device it is updated to record that it is now on the device. This had not happened for the missing jobs.
We tried triggering synchronisation through various triggers available but the jobs still failed to appear.
Eventually, we reset the database, at which point the jobs appeared on the device.
On retrieving the logs, the following lines could be seen:
E 02/25/2014 13:55:59:277 00001570
RJSON| rjson_tokener_parse_ex: error object value separator ',' expected at offset 1129; String: 500 Internal Server Error
E 02/25/2014 13:55:59:279 00001570 RubyResultConvertor.h: 176| Incorrect json body.Error:JSON error code: 11; Offset: 1129
E 02/25/2014 13:56:01:429 00001570
RJSON| rjson_tokener_parse_ex: error object value separator ',' expected at offset 1155; String: 500 Internal Server Error
E 02/25/2014 13:56:01:429 00001570 RubyResultConvertor.h: 176| Incorrect json body.Error:JSON error code: 11; Offset: 1155
E 02/25/2014 14:00:25:257 00002fc1
Net| Operation finished with error 6: Couldn't resolve host name
E 02/25/2014 14:00:25:263 00002fc1
Net| CURLNetRequest: METHOD = [POST] URL = [http://localhost:34299/app/Settings/geolocation_callback] BODY = [rho_callback=1&status=ok&available=1&known_position=1&latitude=50.550368&longitude=0.763119&accuracy=8.000000]
E 02/25/2014 14:00:26:275 00001570
HttpServer| Parse startline (1): syntax error: " "
E 02/25/2014 14:00:26:275 00001570
HttpServer| Parsing error
E 02/25/2014 14:00:26:277 00002fcb
Net| Operation finished with error 55: Failed sending data to the peer
E 02/25/2014 14:00:26:278 00002fcb
Net| CURLNetRequest: METHOD = [POST] URL = [http://localhost:34299/app/Settings/geolocation_callback] BODY = [rho_callback=1&status=ok&available=1&known_position=1&latitude=50.550368&longitude=0.763121&accuracy=6.000000]
We know that a message (acknowledged at 14:00) did reach the device since it was read by the user and acknowledged in the same manner as jobs are so whatever happened did not affect all of the models.
There are no errors recorded against this user on the rhoconnect server at the time.
If anyone can provide any insight into the cause of this issue and what could potentially be done to resolve it, it would be greatly appreciated.
Kind regards,
Graham Bird.
10 Replies
It has come to our attention that this issue may have been addressed in release 4.0.3 of the rhoconnect gem.
Are there release notes for gem updates that we can review to see what bugs have been addressed?
Is there a recommended way for us to keep track of future releases of gems so that we can get them onto a test system and run tests before looking to update live servers?
Currently, I can see the new releases at the following site (but no notes):
all versions of rhoconnect | RubyGems.org | your community gem host
Kind regards,
Graham.
This issue has been fixed in RhoConnect-Client , not RhoConnect. There should be a newest build for RhoMobileSuite 4.0 which includes the fix.
E 02/25/2014 13:55:59:277 00001570 RJSON| rjson_tokener_parse_ex: error object value separator ',' expected at offset 1129; String: 500 Internal Server Error
E 02/25/2014 13:55:59:279 00001570 RubyResultConvertor.h: 176| Incorrect json body.Error:JSON error code: 11; Offset: 1129
E 02/25/2014 13:56:01:429 00001570 RJSON| rjson_tokener_parse_ex: error object value separator ',' expected at offset 1155; String: 500 Internal Server Error
E 02/25/2014 13:56:01:429 00001570 RubyResultConvertor.h: 176| Incorrect json body.Error:JSON error code: 11; Offset: 1155
E 02/25/2014 14:00:25:257 00002fc1 Net| Operation finished with error 6: Couldn't resolve host name
E 02/25/2014 14:00:25:263 00002fc1 Net| CURLNetRequest: METHOD = [POST] URL = [http://localhost:34299/app/Settings/geolocation_callback] BODY = [rho_callback=1&status=ok&available=1&known_position=1&latitude=50.550368&longitude=0.763119&accuracy=8.000000]
E 02/25/2014 14:00:26:275 00001570 HttpServer| Parse startline (1): syntax error: " "
E 02/25/2014 14:00:26:275 00001570 HttpServer| Parsing error
E 02/25/2014 14:00:26:277 00002fcb Net| Operation finished with error 55: Failed sending data to the peer
E 02/25/2014 14:00:26:278 00002fcb Net| CURLNetRequest: METHOD = [POST] URL = [http://localhost:34299/app/Settings/geolocation_callback] BODY = [rho_callback=1&status=ok&available=1&known_position=1&latitude=50.550368&longitude=0.763121&accuracy=6.000000]
Could you try bumping the rhoconfig.txt MinSeverity to 0? This will show us any raw data coming back from rhoconnect. Another helpful tool (if you're on linux or mac) is to use ngrep so we can see what traffic is coming back from rhoconnect. Other than that it will be challenging to debug this unless I have some kind of sample code or sample app to work with. Here's the ngrep command I use to check rhoconnect (if it is running on port 9292):
If you're on OSX Mavericks:
sudo ngrep -q -W byline -d lo0 '' 'port 9292'
Other OSX versions & Linux:
sudo ngrep -d lo0 -W byline port 9292
Lars,
I will have to see what I can do with regards to the logging.
I am afraid that we did not see this issue during our testing period and have only seen it since deploying it to our customer (and only once so far) and we cannot easily update the customer's applications in the field with this kind of change.
We will have to run some tests on our test system and see if we can repeat the issue and provide you with the logs from there if we are able to.
Regards,
Graham.
Graham,
I've not got any good news for you, but on the basis that misery loves company, we're suffering for a very similar error.
It seems to me to be caused on the sync following a sync where a "raise Rhoconnect::Model::Exception.new" is performed. We've actually become more aware of this after being asked by Moto to raise more errors in the create and query methods rather than in the login method which does not seem to be handled at all well by the Rho client.
We too seem to be losing data - though we're by no means certain at what point.
Could I ask what versions you are using and how recently you've upgraded?
Cheers
John
We're using Rhoconnect 4.0.0.
This was installed on the server in early February.
The application is also on 4.0.0.
Regards,
Graham.
Moving to the . do you have any thoughts?
The fix for 4.0 is now available here: https://developer.motorolasolutions.com/docs/DOC-2163
As Max has mentioned, this was fixed in RhoConnect-Client. It will be available with the public 4.1 release. If you have a support contract, please file a support ticket requesting for the fix attached to SPR25327.
Brian
It is possibly worth mentioning that the unreadable characters in the line
Parse startline (1): syntax error: " "
show up as "NAK ETX SOH" in Notepad++ (Negative acknowledgement, End of text, Start of heading)
Kind regards,
Graham Bird.