Fixed Python3 TypeError

[shaansubbaiah]

For TypeError: ord() expected string of length 1, but int found In Python3 indexing a bytes object returns an integer, ord() is not required. stream_id = ord(message.data[0]) -> stream_id = message.data[0]

For TypeError: must be str, not bytes file_object.write(data[1:]) -> file_object.write(data[1:].decode("utf-8"))

[srevinsaju]

Seems like I worked on a different fix @shaansubbaiah What is your test plan you have followed

I feel the fix is not correct, but I may be wrong too. @quozl may have his opinion.

[shaansubbaiah]

Hi Srevin, this was supposed to fix #909, issue pops up when opening and closing a web activity; have tried it on Gears Activity and the error TypeError: ord() expected string of length 1, but int found seems to have gone. Edit: On the moon activity

Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/dbus/connection.py", line 607, in msg_reply_handler
    *message.get_args_list()))
  File "/usr/lib/python3.7/dist-packages/jarabe/apisocket.py", line 211, in error_handler
    self._client.send_error(info["close_request"], error)
  File "/usr/lib/python3.7/dist-packages/jarabe/apisocket.py", line 270, in send_error
    self._session.send_message(json.dumps(response))
  File "/usr/lib/python3.7/json/__init__.py", line 231, in dumps
    return _default_encoder.encode(obj)
  File "/usr/lib/python3.7/json/encoder.py", line 199, in encode
    chunks = self.iterencode(o, _one_shot=True)
  File "/usr/lib/python3.7/json/encoder.py", line 257, in iterencode
    return _iterencode(o, 0)
  File "/usr/lib/python3.7/json/encoder.py", line 179, in default
    raise TypeError(f'Object of type {o.__class__.__name__} '
TypeError: Object of type DBusException is not JSON serializable

Issue seems to arise from encoder.py?

[srevinsaju]

@shaansubbaiah Thanks, I will test it with Gears Activity and let you know soon

[srevinsaju]

@shaansubbaiah tested, I couldn't reproduce the error mentioned by @quozl . Could you give me a detailed help on how to test / reproduce this error (without your PR) Thanks a lot

[shaansubbaiah]

Did you check if gwebsockets is at v0.7 (the live build I had came with 0.6) and Enabled debugging? Simply opening and closing the Gears Activity should reproduce the error; I haven't done anything else.

[srevinsaju]

@shaansubbaiah I am testing it on the latest 0.116 Build on Manjaro Kyria 19.0 This is my logs I have set the logger levels and gwebsockets is 0.7

[shaansubbaiah]

Please check shell.log :). Even my Gears Activity log doesn't show any error.

[srevinsaju]

Thanks , that helped, I will get back to your PR. I found it in shell.log. Thanks

[srevinsaju]

Thanks @shaansubbaiah. This PR worked in removing the TypeError. I was able to remove the other logs. Verified the the entry and exit of data before and after changing the ord to be same.

[quozl]

Thanks. I accept that your change has stopped the error, but I don't yet fully understand why your change worked, and how to test the code that was changed,. Your commit message on 95675f2 didn't help.

Please rewrite the commit message. See making commits and guide for reviewers. In particular some or all of the narrative you placed in the pull request opening comment should be in the commit message, and the commit message should try to explain what the problem was, how it was fixed, and how you tested that the code works as it should.

[quozl]

Fixes https://github.com/sugarlabs/sugar/issues/909.

[shaansubbaiah]

Sorry for the sloppy commit message, I'll update it shortly. I've always thought there was a limit to the length of the commit messages, turns out the 50 char length is only for the first line.

[quozl]

I see how you could have come to that conclusion. The information out there is somewhat variable. I don't have a problem with line widths of up to 76 characters, so that I can use "git log" in a standard terminal. Unnecessary words should be removed from the first line, and the detail added in lines following the blank line. Also check the style used in the repository you are working on.

[srevinsaju]

@quozl How did the integer come instead of the character? I still cannot understand what actually happened between the lines / commits

[shaansubbaiah]

@quozl I have updated the commit message. (Also, for some reason, editing the commit message using a GUI text editor like Kate didn't work. I had to use Nano CLI editor and make the changes)

@srevinsaju I believe that is due to a difference in how python2 and python3 index byte buffers.

Edit: Found this guide on guide commits very helpful in figuring out commit message lengths.

[quozl]

Thanks. Much nicer commit message, and I understand better why you made the changes you did.

For the change to DatastoreAPI.load.on_data, your fix is to decode the bytes into utf-8, but the only reason you gave is that it stops the error. The error happened when the file is created and written to. I don't see a corresponding change to when the file is read. Are you sure the file is read and sent back to the client intact? How did you test that? Might it be better to change the file open mode (in the two places) to binary?

For the change to _message_received_cb, again it looks like you're focusing on fixing the error but not on the underlying problem; that the code was not properly ported from Python 2 and tested. Our Python 3 Porting Guide mentions the need to "Check for use of binary data, especially in files, pipes, and subprocesses,", and as it looks very much like this was not done, perhaps it should be done now.

This problem looks deeper than fixing a couple of lines. It goes to the heart of handing the bytes data exchanged with the activity over the web socket.

Another test is whether you can resume a web activity from the journal and have the previously saved data properly loaded, even if it is binary. You may have to look for a web activity that does that. I can't remember which ones do.

[quozl]

@quozl How did the integer come instead of the character? I still cannot understand what actually happened between the lines / commits

Sorry, I couldn't figure out what you are referring to.

It might help to look at the changes to this file between 0.112 and 0.116, which covers the time period of the port to Python 3.

git diff v0.112..v0.116 -- src/jarabe/apisocket.py

No sign of changes to the file mode, so not really ported yet?

[srevinsaju]

Thanks @quozl and @shaansubbaiah The newer commit message explained everything perfectly to me. I went away to test it on python2 and python3, quite astounded by the results. It looks cool!

[quozl]

Let us know if there's something we can fix in the porting guide.

[shaansubbaiah]

@quozl As mentioned earlier, with and without the changes in the PR I get this error in shell.log . Could this also be related to the Porting from Python2 to 3 ? Seems to be originating from encoder.py, but I'm not exactly sure.

1584360319.744499 DEBUG gwebsockets: Received binary message, length 16
1584360319.744759 DEBUG gwebsockets: Got data, length 68
1584360319.744881 DEBUG gwebsockets: Received text message b'{"method":"close_stream","id":14,"params":[1],"jsonrpc":"2.0"}'
1584360319.976344 DEBUG gwebsockets: Sending text message {"result": [], "error": null, "id": 13}
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/dbus/connection.py", line 607, in msg_reply_handler
    *message.get_args_list()))
  File "/usr/lib/python3.7/dist-packages/jarabe/apisocket.py", line 211, in error_handler
    self._client.send_error(info["close_request"], error)
  File "/usr/lib/python3.7/dist-packages/jarabe/apisocket.py", line 270, in send_error
    self._session.send_message(json.dumps(response))
  File "/usr/lib/python3.7/json/__init__.py", line 231, in dumps
    return _default_encoder.encode(obj)
  File "/usr/lib/python3.7/json/encoder.py", line 199, in encode
    chunks = self.iterencode(o, _one_shot=True)
  File "/usr/lib/python3.7/json/encoder.py", line 257, in iterencode
    return _iterencode(o, 0)
  File "/usr/lib/python3.7/json/encoder.py", line 179, in default
    raise TypeError(f'Object of type {o.__class__.__name__} '
TypeError: Object of type DBusException is not JSON serializable
1584360319.980641 DEBUG gwebsockets: Got data, length 69
1584360319.980873 DEBUG gwebsockets: Received text message b'{"method":"activity.close","id":15,"params":[],"jsonrpc":"2.0"}'
1584360319.981730 DEBUG gwebsockets: Sending text message {"result": [], "error": null, "id": 15}
1584360319.992085 DEBUG gwebsockets: Got data, length 0

[quozl]

TypeError: Object of type DBusException is not JSON serializable

Watch this; in Python 2;

host:~$ python2
Python 2.7.17 (default, Nov  7 2019, 10:07:09) 
[GCC 7.4.0] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> import dbus
>>> x = dbus.DBusException()
>>> import json
>>> json.dumps(x)
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/usr/lib/python2.7/json/__init__.py", line 244, in dumps
    return _default_encoder.encode(obj)
  File "/usr/lib/python2.7/json/encoder.py", line 207, in encode
    chunks = self.iterencode(o, _one_shot=True)
  File "/usr/lib/python2.7/json/encoder.py", line 270, in iterencode
    return _iterencode(o, 0)
  File "/usr/lib/python2.7/json/encoder.py", line 184, in default
    raise TypeError(repr(o) + " is not JSON serializable")
TypeError: DBusException() is not JSON serializable
>>> █

and in Python 3 ...

>>> json.dumps(x)
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/usr/lib/python3.6/json/__init__.py", line 231, in dumps
    return _default_encoder.encode(obj)
  File "/usr/lib/python3.6/json/encoder.py", line 199, in encode
    chunks = self.iterencode(o, _one_shot=True)
  File "/usr/lib/python3.6/json/encoder.py", line 257, in iterencode
    return _iterencode(o, 0)
  File "/usr/lib/python3.6/json/encoder.py", line 180, in default
    o.__class__.__name__)
TypeError: Object of type 'DBusException' is not JSON serializable
>>> █

From this it would seem that the problem is that apisocket.py is attempting to convert an exception to JSON, which is impossible in both Python 2 and Python 3. You would need to find out why it is trying to do that.

Looking back through the trace, DatastoreAPI.save.error_handler at your line 211 is the trigger.

Converting that into a narrative; when the datastore object is saved, a file is created, a stream monitor for close is set up, and when the close occurs the datastore is asked to update, which specifies an error handler. The update fails though we don't know why. (perhaps the uid or metadata is invalid). The error handler is called and tries to send the exception back to the client.

It is possible that this error handling code path was not tested by @dnarvaez.

You could debug further by finding out what the exception is. It might be that the exception is also caused by our failure to port the module to Python 3.

[quozl]

Overall, a more correct approach is to port the module to Python 3, by careful analysis of every data flow in light of the changes required when porting any code from Python 2 to Python 3. It is a process of staring at the code for hours if necessary, reverse engineering, documenting for yourself, maybe running a few tests to prove your theories, and then coming up with changes that should have happened in aa18879e9717dfe2d30f249549e9a43d6dd6da4f.

[shaansubbaiah]

@quozl could you please explain your workflow in coding/debugging Sugar and its components? I have followed your advice earlier, SSHing to the VM and editing the files through VSCode on my main computer speeds up things quite a bit. One issue I keep facing is that for every change I have to log out and log in to Sugar again. Is there a workaround or a more efficient way to go about it?

[quozl]

Sure.

Only have to restart for changes to Sugar. Changes to Toolkit may need a restart if you are testing Sugar. Otherwise changes to Toolkit are picked up by an activity when it starts.

I've two methods I use to restart under IDE control. Both use a Makefile. One method not used for a while is to drive the VM over SSH or via xdotool to do something. Second method is preferred; add code that will detect a restart request via filesystem and call sys.exit or os.execv or similar.

https://github.com/sugarlabs/record-activity/commit/2703fc2fc0803f056faedd69fb95d82cc055b63d is an example on the Record activity port to GTK 3 branch. A Makefile does a touch go on the VM, and this repeating task in the activity detects it and calls the activity again.

But take care; sometimes the tooling you do can undo your testing. In this case on the Record activity, on certain laptops (not VMs) the camera could not be opened after being closed so rapidly, or the camera wasn't actually closed before the os.execv took effect. It depended on the kernel driver, which was unique for the camera type. I had to add an explicit close of GStreamer to finish tooling on that laptop. Always remember to do a final test without any automation tooling, and try not to leave the tooling behind in the pull request. You can use git stash or branches to help with that.

[srevinsaju]

@shaansubbaiah, maybe this might benefit you too. In my case where I couldn't use a VM, I used to test sugar by having a native Linux installation (say, Ubuntu, Fedora or Arch Linux) and then running two desktop environments at the same time.

I too like you, used vscode and vim on the native KDE Plasma Desktop environment and then used switch user to create another TTY on TTY2. Launch sugar on TTY2 by selecting in drop down tab. Make changes in your vscode, save it locally, or do python3 setup.py dev for testing purposes to create a symlink on your test files to the ~/Activities directory. Then use Ctrl + Alt + F1 and Ctrl + Alt + F2` to switch between desktop environments realtime

[quozl]

Yes, that works too, although collaboration testing does need separate IP addresses and this is hard to do with separate virtual consoles. You can also use technologies like xvfb, RDP, or VNC in order to avoid VMs.

[shaansubbaiah]

Thanks, I'll try them out.

[shaansubbaiah]

Just set up the Live Build v117 from the Mailing List, working on porting.

[shaansubbaiah]

@quozl is there any documentation for the apisocket file?

Also, I should be able to view the data sent at each step by using the logger?

[quozl]

I don't know of any documentation. Make sure you check gwebsockets, the mailing list archives at the time of the first commits, and our Wiki. The original author vanished, we never found out what happened to them.

Yes, data can certainly be logged. If you are not seeing logs, make sure you flush stderr, because it is buffered in Python 3.

Also, it is critical to bring up a Python 2 system for comparison debugging, that way we can be more certain of the changes. I suggest OLPC OS 18.04 as a working Python 2 release of Sugar that can be edited to add debugging. Create a new branch from the version tag to demonstrate any debugging added.

[shaansubbaiah]

@quozl , printing the error I get:

1585224824.453091 DEBUG PY3-VM: ERROR:
1585224824.453414 DEBUG PY3-VM: org.freedesktop.DBus.Python.ValueError: Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/dbus/service.py", line 707, in _message_cb
    retval = candidate_method(self, *args, **keywords)
  File "/usr/lib/python3.7/dist-packages/carquinyol/datastore.py", line 373, in update
    lambda * args: self._update_completion_cb(async_cb,
  File "/usr/lib/python3.7/dist-packages/carquinyol/filestore.py", line 49, in store
    raise ValueError('No file at %r' % file_path)
ValueError: No file at dbus.String('/home/shaan/.sugar/default/com.garycmartin.Moon/instance/1585224824')

1585224824.453572 DEBUG PY3-VM: INFO CLOSE REQUEST:
1585224824.453698 DEBUG PY3-VM: {'method': 'close_stream', 'id': 14, 'params': [1], 'jsonrpc': '2.0'}

It is due to apisocket.py not saving the file for the Moon Activity at /home/shaan/.sugar/default/com.garycmartin.Moon/instance/1585224824 . This does not happen with the gears activity (perhaps they store files differently, I have to check it out.)

The ../instance/{timestamp}/ directory remains empty when I try to list files before, after and while the Moon Activity is open. I have used inotifywatch to check if files are being created and got this output: (inotifywatch is checking the ~/.sugar/default/com.garycmartin.Moon/ directory recursively for 10 seconds during which I open and close the activity once)

shaan@debian:~/.sugar/default/com.garycmartin.Moon$ inotifywatch -v -t 10 -r /home/shaan/.sugar/default/com.garycmartin.Moon/
Establishing watches...
Setting up watch(es) on /home/shaan/.sugar/default/com.garycmartin.Moon/
OK, /home/shaan/.sugar/default/com.garycmartin.Moon/ is now being watched.
Total of 4 watches.
Finished establishing watches, now collecting statistics.
Will listen for events for 10 seconds.
total  access  modify  close_write  close_nowrite  open  moved_from  create  filename
37     13      0       0            12             12    0           0       /home/shaan/.sugar/default/com.garycmartin.Moon/
13     2       3       2            1              3     1           1       /home/shaan/.sugar/default/com.garycmartin.Moon/instance/

This shows that it has created a file? I'm not exactly sure what the issue is, I'll be going through the Datastore Documentation and inspecting the Moon Activity.

Full log here. (Gdrive link, fpaste expires after a day, wasn't sure when you would have time to go through this comment.) Also is all the data in the ~/.sugar/default/datastore and ~/.sugar/default/data is stored in plaintext? It appears so.

Sorry it has been awhile, had some college assignments and projects preponed due to the current situation with the virus.

[quozl]

Thanks for the update.

[shaansubbaiah]

@quozl As mentioned earlier, the issue had occurred only with the Moon activity and not with the Gears activity. My understanding based on what I have read in the DataStore documentation and going through the logs is that

1. Stream is created -> Data loaded/ stored -> Stream closed.
2. The instance folder at ~/.sugar/default/{activity name} is used as some sort of temporary storage before it is moved to the DataStore directory at ~/.sugar/default/datastore.

I have observed that the Moon Activity opens the Stream twice. Open 1st stream -> Open 2nd stream -> Save Data -> (instance is emptied) Close 1st stream -> Close 2nd stream (Generates error as the data at the instance folder is missing).

Log here:

1585664098.542321 DEBUG gwebsockets: Received text message b'{"method":"open_stream","id":11,"params":[],"jsonrpc":"2.0"}'
1585664098.542874 DEBUG gwebsockets: Sending text message {"result": [0], "error": null, "id": 11}
1585664098.543675 DEBUG gwebsockets: Got data, length 66
1585664098.544173 DEBUG gwebsockets: Received text message b'{"method":"open_stream","id":12,"params":[],"jsonrpc":"2.0"}'
1585664098.544683 DEBUG gwebsockets: Sending text message {"result": [1], "error": null, "id": 12}
1585664098.545433 DEBUG gwebsockets: Got data, length 415
1585664098.546014 DEBUG gwebsockets: Received text message b'{"method":"datastore.save","id":13,"params":["7750f837-db5b-409d-8d25-c9024a8d497d",{"timestamp":1585151101,"title":"Shaan Moon Activity","uid":"7750f837-db5b-409d-8d25-c9024a8d497d","title_set_by_user":"1","creation_time":1585151101,"activity":"com.garycmartin.Moon","checksum":"1441a7909c087dbbe7ce59881b9df8b9","filesize":"15","activity_id":"fe11c941b3b2337c9d2f395d82fe06364b30d62c"},0],"jsonrpc":"2.0"}'
1585664098.547274 DEBUG PY3-VM: DATA STORE API save()
1585664098.547662 DEBUG PY3-VM: uid
1585664098.548018 DEBUG PY3-VM: 7750f837-db5b-409d-8d25-c9024a8d497d
1585664098.548545 DEBUG PY3-VM:  metadata:
1585664098.548766 DEBUG PY3-VM: {'timestamp': 1585151101, 'title': 'Shaan Moon Activity', 'uid': '7750f837-db5b-409d-8d25-c9024a8d497d', 'title_set_by_user': '1', 'creation_time': 1585151101, 'activity': 'com.garycmartin.Moon', 'checksum': '1441a7909c087dbbe7ce59881b9df8b9', 'filesize': '15', 'activity_id': 'fe11c941b3b2337c9d2f395d82fe06364b30d62c'}
1585664098.549025 DEBUG PY3-VM:  stream_id:
1585664098.549250 DEBUG PY3-VM: 0
1585664098.556527 DEBUG PY3-VM: OPENED A BINARY FILE @
1585664098.556987 DEBUG PY3-VM: /home/shaan/.sugar/default/com.garycmartin.Moon/instance/1585664098
1585664098.557275 DEBUG PY3-VM: <class 'str'>
1585664098.557628 DEBUG gwebsockets: Sending text message {"result": [], "error": null, "id": 13}
1585664098.558614 DEBUG gwebsockets: Got data, length 415
1585664098.559231 DEBUG gwebsockets: Received text message b'{"method":"datastore.save","id":14,"params":["7750f837-db5b-409d-8d25-c9024a8d497d",{"timestamp":1585151101,"title":"Shaan Moon Activity","uid":"7750f837-db5b-409d-8d25-c9024a8d497d","title_set_by_user":"1","creation_time":1585151101,"activity":"com.garycmartin.Moon","checksum":"1441a7909c087dbbe7ce59881b9df8b9","filesize":"15","activity_id":"fe11c941b3b2337c9d2f395d82fe06364b30d62c"},1],"jsonrpc":"2.0"}'
1585664098.560868 DEBUG PY3-VM: DATA STORE API save()
1585664098.561305 DEBUG PY3-VM: uid
1585664098.562127 DEBUG PY3-VM: 7750f837-db5b-409d-8d25-c9024a8d497d
1585664098.562791 DEBUG PY3-VM:  metadata:
1585664098.563410 DEBUG PY3-VM: {'timestamp': 1585151101, 'title': 'Shaan Moon Activity', 'uid': '7750f837-db5b-409d-8d25-c9024a8d497d', 'title_set_by_user': '1', 'creation_time': 1585151101, 'activity': 'com.garycmartin.Moon', 'checksum': '1441a7909c087dbbe7ce59881b9df8b9', 'filesize': '15', 'activity_id': 'fe11c941b3b2337c9d2f395d82fe06364b30d62c'}
1585664098.563725 DEBUG PY3-VM:  stream_id:
1585664098.564133 DEBUG PY3-VM: 1
1585664098.565575 DEBUG PY3-VM: OPENED A BINARY FILE @
1585664098.565937 DEBUG PY3-VM: /home/shaan/.sugar/default/com.garycmartin.Moon/instance/1585664098
1585664098.566167 DEBUG PY3-VM: <class 'str'>
1585664098.566454 DEBUG gwebsockets: Sending text message {"result": [], "error": null, "id": 14}
1585664098.568335 DEBUG gwebsockets: Got data, length 90
1585664098.569035 DEBUG gwebsockets: Received binary message, length 16
1585664098.569811 DEBUG gwebsockets: Received text message b'{"method":"close_stream","id":15,"params":[0],"jsonrpc":"2.0"}'
1585664098.571831 DEBUG gwebsockets: Got data, length 90
1585664098.572204 DEBUG gwebsockets: Received binary message, length 16
1585664098.572531 DEBUG gwebsockets: Received text message b'{"method":"close_stream","id":16,"params":[1],"jsonrpc":"2.0"}'
1585664098.857101 DEBUG gwebsockets: Sending text message {"result": [], "error": null, "id": 15}
1585664098.857396 DEBUG PY3-VM: ERROOR:
1585664098.857453 DEBUG PY3-VM: org.freedesktop.DBus.Python.ValueError: Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/dbus/service.py", line 707, in _message_cb
    retval = candidate_method(self, *args, **keywords)
  File "/usr/lib/python3.7/dist-packages/carquinyol/datastore.py", line 373, in update
    lambda * args: self._update_completion_cb(async_cb,
  File "/usr/lib/python3.7/dist-packages/carquinyol/filestore.py", line 49, in store
    raise ValueError('No file at %r' % file_path)
ValueError: No file at dbus.String('/home/shaan/.sugar/default/com.garycmartin.Moon/instance/1585664098')

The files in datastore are saved in plaintext so we don't have to open them as binary files. The previous fixes: Removing the ord() and Converting the data to String using .decode('UTF-8') seem to work normally. I am able to resume the gears activity. I had renamed the moon activity and even that wasn't lost when I resumed it.

I shall try a few more web activities and report back.

Edit: No issue with the Find-words-activity but I don't think it stores anything

Edit 2: While using the Find-words-activity the same issue popped up (opens 3 streams), but the previously generated words are loaded properly. It stores words for the puzzle.

[quozl]

Thanks for the update. Earlier I said you must find out what happens on Python 2. Please do try that and compare. This is because we have a reasonable expectation that any problem in this code was introduced by incomplete port to Python 3. It will also give you a baseline to compare against.

[shaansubbaiah]

I had tried that earlier, the VM kept freezing and Python 2 kept crashing without any error message. I was prompted to update some packages in Ubuntu while setting up SSH, not sure if that had anything to do with it. I will install it again and test.

[quozl]

Okay. I don't remember what Ubuntu release you have chosen to get a Python 2 environment, but ubuntu.md shows what works and what doesn't. i.e. use 19.04, or 18.04.

OLPC OS 18.04.0 here is my curated derivative with a later Sugar but still Python 2.

[shaansubbaiah]

I had installed the OLPC OS 18.04. Also when I login to Sugar, the display resolution scales to 4K and it becomes really hard to operate. Attempting to resize scales UI from 4K to 1080p making everything 4x smaller. I have not had this issue with the other VMs installed. I have started installing the OS again, I'll avoid the update this time and see if the issue appears again.

[quozl]

Ah, yes, that's possible. OLPC OS 18.04 is intended for laptops with a resolution of about 1366x768 with an external monitor option in clone mode, and contains a patch to /usr/bin/sugar that facilitates that. In turn because Sugar doesn't have multiple display support.

To fix, you might try editing the file to remove these lines;

# OLPC NL3 external monitor and power button support
if [ -e /sys/devices/virtual/dmi/id/bios_version ]; then
    gsettings set org.gnome.settings-daemon.plugins.media-keys active false
    gsettings set org.gnome.settings-daemon.plugins.xrandr default-monitors-setup clone
    unity-settings-daemon &
fi

[shaansubbaiah]

@quozl after a fresh install of the OLPC 18.04 OS, installing only openssh-client and enabling the debugger, I get the following errors:

Opening and closing the Moon Activity

Initially

1585833574.988766 ERROR dbus.connection: Unable to set arguments (None,) according to signature u's': <type 'exceptions.TypeError'>: Expected a string or unicode object
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/dbus/connection.py", line 604, in msg_reply_handler
    reply_handler(*message.get_args_list(**get_args_opts))
  File "/usr/lib/python2.7/dist-packages/dbus/proxies.py", line 401, in _introspect_reply_handler
    self._introspect_execute_queue()
  File "/usr/lib/python2.7/dist-packages/dbus/proxies.py", line 387, in _introspect_execute_queue
    proxy_method(*args, **keywords)
  File "/usr/lib/python2.7/dist-packages/dbus/proxies.py", line 137, in __call__
    **keywords)
  File "/usr/lib/python2.7/dist-packages/dbus/connection.py", line 584, in call_async
    message.append(signature=signature, *args)
TypeError: Expected a string or unicode object

and then

Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/dbus/connection.py", line 607, in msg_reply_handler
    *message.get_args_list()))
  File "/usr/lib/python2.7/dist-packages/jarabe/apisocket.py", line 210, in error_handler
    self._client.send_error(info["close_request"], error)
  File "/usr/lib/python2.7/dist-packages/jarabe/apisocket.py", line 267, in send_error
    self._session.send_message(json.dumps(response))
  File "/usr/lib/python2.7/json/__init__.py", line 244, in dumps
    return _default_encoder.encode(obj)
  File "/usr/lib/python2.7/json/encoder.py", line 207, in encode
    chunks = self.iterencode(o, _one_shot=True)
  File "/usr/lib/python2.7/json/encoder.py", line 270, in iterencode
    return _iterencode(o, 0)
  File "/usr/lib/python2.7/json/encoder.py", line 184, in default
    raise TypeError(repr(o) + " is not JSON serializable")
TypeError: DBusException(dbus.String(u'Traceback (most recent call last):\n  File "/usr/lib/python2.7/dist-packages/dbus/service.py", line 707, in _message_cb\n    retval = candidate_method(self, *args, **keywords)\n  File "/usr/lib/python2.7/dist-packages/carquinyol/datastore.py", line 375, in update\n    lambda * args: self._update_completion_cb(async_cb,\n  File "/usr/lib/python2.7/dist-packages/carquinyol/filestore.py", line 47, in store\n    raise ValueError(\'No file at %r\' % file_path)\nValueError: No file at dbus.String(u\'/home/ss/.sugar/default/com.garycmartin.Moon/instance/1585833595\')\n'),) is not JSON serializable

TypeError: DBusException(dbus.String(u'Traceback (most recent call last):\n  File "/usr/lib/python2.7/dist-packages/dbus/service.py", line 707, in _message_cb\n    retval = candidate_method(self, *args, **keywords)\n  File "/usr/lib/python2.7/dist-packages/carquinyol/datastore.py", line 375, in update\n    lambda * args: self._update_completion_cb(async_cb,\n  File "/usr/lib/python2.7/dist-packages/carquinyol/filestore.py", line 47, in store\n    raise ValueError(\'No file at %r\' % file_path)\nValueError: No file at dbus.String(u\'/home/ss/.sugar/default/com.garycmartin.Moon/instance/1585833595\')\n'),) is not JSON serializable
1585833672.466127 ERROR dbus.connection: Unable to set arguments (None,) according to signature u's': <type 'exceptions.TypeError'>: Expected a string or unicode object
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/dbus/connection.py", line 604, in msg_reply_handler
    reply_handler(*message.get_args_list(**get_args_opts))
  File "/usr/lib/python2.7/dist-packages/dbus/proxies.py", line 401, in _introspect_reply_handler
    self._introspect_execute_queue()
  File "/usr/lib/python2.7/dist-packages/dbus/proxies.py", line 387, in _introspect_execute_queue
    proxy_method(*args, **keywords)
  File "/usr/lib/python2.7/dist-packages/dbus/proxies.py", line 137, in __call__
    **keywords)
  File "/usr/lib/python2.7/dist-packages/dbus/connection.py", line 584, in call_async
    message.append(signature=signature, *args)
TypeError: Expected a string or unicode object

This issue was present before the port to Python3 ?

Edit: The last log is also from the Moon activity

[chimosky]

This issue was present before the port to Python3 ?

Yes, OLPC 18.04 runs python2 activities and not python3. I'm guessing you're running both at master, you can look at running the gtk2 branch of moon activity or checking out the change before the port to python3 and do same for gears activity.

[shaansubbaiah]

Yes, OLPC 18.04 runs python2 activities and not python3. I'm guessing you're running both at master, you can look at running the gtk2 branch of moon activity or checking out the change before the port to python3 and do same for gears activity.

Thanks! You were right, they both ran Moon v19 from Master. I moved /usr/share/sugar/activities/Moon.activity to another directory and ran setup.py dev for the gtk branch. The issue does not seem to occur.

Is there a list of the activities ported from Python2 to 3? The issue seems to occur on the Find-words-activity also (logs similar to the one at the Live Build v117). This is built with JS.

[chimosky]

Is there a list of the activities ported from Python2 to 3?

Search sugar-activity to see python2 activities and sugar3-activity for python 3 activities. You can view any python 3 activity commit history to see the commit for the port, you can also see this project that was created to track porting to python 3.

The issue seems to occur on the Find-words-activity also Is it the same test environment? Can you share the logs too?

[quozl]

The problem that was being discussed is how a JavaScript activity that writes to the journal twice doesn't succeed in doing so. So I suggested testing to see if this is a Python 3 porting regression.

Moon activity master branch is JavaScript, not Python 3. So I don't agree with @chimosky's most recent comments. :grin:

[quozl]

@quozl after a fresh install of the OLPC 18.04 OS, installing only openssh-client and enabling the debugger, I get the following errors: [...] This issue was present before the port to Python3 ?

Thanks for testing. I agree. The traceback shows a functional similarity, though not a precise similarity. Good to know. Knowing that it isn't an effect of porting means the Python 2 release of Sugar can't be used as a well-functioning standard on which to look for data changes, and instead the problem will have to be fixed by deep analysis of the data flows between the JavaScript activity and Sugar.

You might also check that Moon activity is correctly using the API, by analysis of the source code and tracing execution or tcpdump data packets.

[shaansubbaiah]

Is it the same test environment? Can you share the logs too?

@chimosky Same environment, OLPC 18.04. Logs are similar to the previous one.

---

@quozl It appears that the activities are calling datastore.create and datastore.save multiple times. It appears

1585933641.570952 DEBUG gwebsockets: Received text message {"method":"datastore.create","id":1,"params":[{}],"jsonrpc":"2.0"}
1585933641.581081 DEBUG gwebsockets: Got data, length 144
1585933641.581456 DEBUG gwebsockets: Received text message {"method":"datastore.create","id":2,"params":[{}],"jsonrpc":"2.0"}
1585933641.582134 DEBUG gwebsockets: Received text message {"method":"datastore.create","id":3,"params":[{}],"jsonrpc":"2.0"}
1585933641.795370 DEBUG gwebsockets: Sending text message {"id": 1, "result": ["700a3ede-85f4-4521-b523-a1aff5576e39"], "error": null}
1585933641.807777 DEBUG gwebsockets: Got data, length 65
1585933641.807978 DEBUG gwebsockets: Received text message {"method":"open_stream","id":4,"params":[],"jsonrpc":"2.0"}
1585933641.808159 DEBUG gwebsockets: Sending text message {"id": 4, "result": [0], "error": null}
1585933641.809838 DEBUG gwebsockets: Got data, length 111
1585933641.810202 DEBUG gwebsockets: Received text message {"method":"datastore.save","id":5,"params":["700a3ede-85f4-4521-b523-a1aff5576e39",{},0],"jsonrpc":"2.0"}
1585933641.810851 DEBUG PY2-OLPC: DATA STORE API save()
1585933641.811007 DEBUG PY2-OLPC: uid
1585933641.811099 DEBUG PY2-OLPC: 700a3ede-85f4-4521-b523-a1aff5576e39
1585933641.811201 DEBUG PY2-OLPC:  metadata:
1585933641.811277 DEBUG PY2-OLPC: {}
1585933641.811353 DEBUG PY2-OLPC:  stream_id:
1585933641.811442 DEBUG PY2-OLPC: 0
1585933641.811682 DEBUG PY2-OLPC: OPENED A BINARY FILE @
1585933641.811780 DEBUG PY2-OLPC: /home/ss/.sugar/default/org.sugarlabs.FindWords/instance/1585933641
1585933641.811855 DEBUG PY2-OLPC: <type 'str'>
1585933641.811961 DEBUG gwebsockets: Sending text message {"id": 5, "result": [], "error": null}
1585933641.814559 DEBUG gwebsockets: Got data, length 242
1585933641.814864 DEBUG gwebsockets: Received binary message, length 167
1585933641.815016 DEBUG PY2-OLPC: Type of streamid:
1585933641.815107 DEBUG PY2-OLPC: <type 'str'>
1585933641.815245 DEBUG gwebsockets: Received text message {"method":"close_stream","id":6,"params":[0],"jsonrpc":"2.0"}
1585933642.030567 DEBUG gwebsockets: Sending text message {"id": 2, "result": ["660d37bd-dc29-4e09-b7e0-7e1c7c5e1aed"], "error": null}
1585933642.040888 DEBUG gwebsockets: Sending text message {"id": 3, "result": ["980c6265-d1f4-4fed-93aa-8f5b77ce80a8"], "error": null}
1585933642.041639 DEBUG gwebsockets: Got data, length 65
1585933642.042030 DEBUG gwebsockets: Received text message {"method":"open_stream","id":7,"params":[],"jsonrpc":"2.0"}
1585933642.042278 DEBUG gwebsockets: Sending text message {"id": 7, "result": [0], "error": null}
1585933642.043267 DEBUG gwebsockets: Got data, length 65
1585933642.043493 DEBUG gwebsockets: Received text message {"method":"open_stream","id":8,"params":[],"jsonrpc":"2.0"}
1585933642.043717 DEBUG gwebsockets: Sending text message {"id": 8, "result": [1], "error": null}
1585933642.045229 DEBUG gwebsockets: Got data, length 111
1585933642.045574 DEBUG gwebsockets: Received text message {"method":"datastore.save","id":9,"params":["660d37bd-dc29-4e09-b7e0-7e1c7c5e1aed",{},0],"jsonrpc":"2.0"}
1585933642.046489 DEBUG PY2-OLPC: DATA STORE API save()
1585933642.046629 DEBUG PY2-OLPC: uid
1585933642.046718 DEBUG PY2-OLPC: 660d37bd-dc29-4e09-b7e0-7e1c7c5e1aed
1585933642.046807 DEBUG PY2-OLPC:  metadata:
1585933642.046888 DEBUG PY2-OLPC: {}
1585933642.046963 DEBUG PY2-OLPC:  stream_id:
1585933642.047033 DEBUG PY2-OLPC: 0
1585933642.047356 DEBUG PY2-OLPC: OPENED A BINARY FILE @
1585933642.047769 DEBUG PY2-OLPC: /home/ss/.sugar/default/org.sugarlabs.FindWords/instance/1585933642
1585933642.047858 DEBUG PY2-OLPC: <type 'str'>
1585933642.047970 DEBUG gwebsockets: Sending text message {"id": 9, "result": [], "error": null}
1585933642.048737 DEBUG gwebsockets: Got data, length 112
1585933642.048973 DEBUG gwebsockets: Received text message {"method":"datastore.save","id":10,"params":["980c6265-d1f4-4fed-93aa-8f5b77ce80a8",{},1],"jsonrpc":"2.0"}
1585933642.049973 DEBUG PY2-OLPC: DATA STORE API save()
1585933642.050137 DEBUG PY2-OLPC: uid
1585933642.050227 DEBUG PY2-OLPC: 980c6265-d1f4-4fed-93aa-8f5b77ce80a8
1585933642.050316 DEBUG PY2-OLPC:  metadata:
1585933642.050388 DEBUG PY2-OLPC: {}
1585933642.050469 DEBUG PY2-OLPC:  stream_id:
1585933642.050540 DEBUG PY2-OLPC: 1
1585933642.050787 DEBUG PY2-OLPC: OPENED A BINARY FILE @
1585933642.050882 DEBUG PY2-OLPC: /home/ss/.sugar/default/org.sugarlabs.FindWords/instance/1585933642
1585933642.050962 DEBUG PY2-OLPC: <type 'str'>
1585933642.051066 DEBUG gwebsockets: Sending text message {"id": 10, "result": [], "error": null}
1585933642.051710 DEBUG gwebsockets: Got data, length 243
1585933642.052184 DEBUG gwebsockets: Received binary message, length 167
1585933642.052372 DEBUG PY2-OLPC: Type of streamid:
1585933642.052685 DEBUG PY2-OLPC: <type 'str'>
1585933642.052862 DEBUG gwebsockets: Received text message {"method":"close_stream","id":11,"params":[0],"jsonrpc":"2.0"}
1585933642.053323 DEBUG gwebsockets: Got data, length 243
1585933642.053517 DEBUG gwebsockets: Received binary message, length 167
1585933642.053631 DEBUG PY2-OLPC: Type of streamid:
1585933642.053714 DEBUG PY2-OLPC: <type 'str'>
1585933642.053843 DEBUG gwebsockets: Received text message {"method":"close_stream","id":12,"params":[1],"jsonrpc":"2.0"}
1585933642.170768 DEBUG gwebsockets: Sending text message {"id": 6, "result": [], "error": null}
1585933642.388364 DEBUG gwebsockets: Sending text message {"id": 11, "result": [], "error": null}
1585933642.390156 DEBUG PY2-OLPC: ERROOR:
1585933642.390406 DEBUG PY2-OLPC: org.freedesktop.DBus.Python.ValueError: Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/dbus/service.py", line 707, in _message_cb
    retval = candidate_method(self, *args, **keywords)
  File "/usr/lib/python2.7/dist-packages/carquinyol/datastore.py", line 375, in update
    lambda * args: self._update_completion_cb(async_cb,
  File "/usr/lib/python2.7/dist-packages/carquinyol/filestore.py", line 47, in store
    raise ValueError('No file at %r' % file_path)
ValueError: No file at dbus.String(u'/home/ss/.sugar/default/org.sugarlabs.FindWords/instance/1585933642')

1585933642.390633 DEBUG PY2-OLPC: INFO CLOSE REQUEST:
1585933642.390771 DEBUG PY2-OLPC: {u'jsonrpc': u'2.0', u'params': [1], u'method': u'close_stream', u'id': 12}
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/dbus/connection.py", line 607, in msg_reply_handler
    *message.get_args_list()))
  File "/usr/lib/python2.7/dist-packages/jarabe/apisocket.py", line 228, in error_handler
    self._client.send_error(info["close_request"], error)
  File "/usr/lib/python2.7/dist-packages/jarabe/apisocket.py", line 292, in send_error
    self._session.send_message(json.dumps(response))
  File "/usr/lib/python2.7/json/__init__.py", line 244, in dumps
    return _default_encoder.encode(obj)
  File "/usr/lib/python2.7/json/encoder.py", line 207, in encode
    chunks = self.iterencode(o, _one_shot=True)
  File "/usr/lib/python2.7/json/encoder.py", line 270, in iterencode
    return _iterencode(o, 0)
  File "/usr/lib/python2.7/json/encoder.py", line 184, in default
    raise TypeError(repr(o) + " is not JSON serializable")
TypeError: DBusException(dbus.String(u'Traceback (most recent call last):\n  File "/usr/lib/python2.7/dist-packages/dbus/service.py", line 707, in _message_cb\n    retval = candidate_method(self, *args, **keywords)\n  File "/usr/lib/python2.7/dist-packages/carquinyol/datastore.py", line 375, in update\n    lambda * args: self._update_completion_cb(async_cb,\n  File "/usr/lib/python2.7/dist-packages/carquinyol/filestore.py", line 47, in store\n    raise ValueError(\'No file at %r\' % file_path)\nValueError: No file at dbus.String(u\'/home/ss/.sugar/default/org.sugarlabs.FindWords/instance/1585933642\')\n'),) is not JSON serializable
1585933647.442990 DEBUG gwebsockets: Got data, length 69

I have created a TCP Dump while Opening Find-words-activity -> Clicking on Random Word Generate Button -> Closing the activity. Linked here. The file is very large as I created it without filtering anything. I opened it in Wireshark and was unable to figure anything out, hopefully it makes sense to someone else. I have to spend some time and learn how to analyse these packets. This happens in the Find-words-activity when I click on the button to generate some random words. I'll go through the activity code and try to figure something out.

[shaansubbaiah]

@quozl I followed your advice and attempted to create a TCPdump using the Apisocket port. Upon termination, I get output saying 0 packets captured, file is empty. (There were multiple processes with the Findwords command, I chose the process ID from the one which had active CPU activity. Edit: checked the other processes as well, had the same port.)

I tried tracing the code executed by clicking the randomize words button in activity.js all the way to {activity-directory}/lib/activity/sugar-web/datastore.js file, did not find anything obvious that could have caused the issue.

Inspecting the activity from within Sugar here were some errors in the console. Not sure if this is directly related to the issue.

[chimosky]

It probably is, always test your changes within sugar as people use sugar. My javascript isn't great so I can't help you here.

[quozl]

tcpdump should be configured with the local network interface, usually lo. Configuring it with the external network interface will show no data.

For the port number, if you can't be sure of it even after using /proc/$PID/environ, there are two other ways to verify it;

• change apisocket or gwebsockets to get the port number that the Gio.SocketService has bound to, and then write it to a file in /tmp for you to look at, (in gwebsockets/server.py, the port number is returned by the Server.start method, and in jarabe/apisocket.py),
• use netstat -anp and look for the jarabe process, and a TCP socket in LISTEN state,

[shaansubbaiah]

I'll try this and post a filtered TCPDump. @quozl Could the issue in env.js here be linked to this?

[shaansubbaiah]

TCPdump generated using sudo tcpdump -i lo -s 0 -w ~/dump.pcap port 41709 linked here

Again, the packets were captured while I clicked on the Random words button. The request is sent thrice, just like the error generated. 41709 is Apisocket port.

The rest of the information is in the dump file.

Also running

$ netstat | grep 47914
tcp        0      0 localhost:47914         localhost:41709         ESTABLISHED
tcp6       0      0 localhost:41709         localhost:47914         ESTABLISHED

$ lsof -i :41709
COMMAND  PID USER   FD   TYPE DEVICE SIZE/OFF NODE NAME
python2 1524   ss   10u  IPv6  33130      0t0  TCP localhost:41709->localhost:47914 (CLOSE_WAIT)
python2 1524   ss   28u  IPv6  28855      0t0  TCP *:41709 (LISTEN)

pid 1524 corresponds to python2 -m jarabe.main