Restart Error - Push Error

[Sandcrawler789]

Install AirNotifier v3.0
Have tried on Ubuntu twice and CentOs7 once (same issues on all 3 servers).

Restart AirNotifier

Make test call (using push service to send APNs).

Log print below received.

1602660704 E [MainThread][root][push.py:153] no active apns connection
1602660704 E [MainThread][root][push.py:177] Traceback (most recent call last):
File "/root/airnotifier/api/push.py", line 174, in post
self.send_response(ACCEPTED)
File "/root/airnotifier/api/init.py", line 212, in send_response
self.finish(data)
File "/root/airnotifier/api/init.py", line 215, in finish
super(APIBaseHandler, self).finish(chunk)
File "/root/.local/share/virtualenvs/airnotifier--hHQdAqd/lib64/python3.6/site-packages/tornado/web.py", line 1119, in finish
raise RuntimeError("finish() called twice")
RuntimeError: finish() called twice
finish() called twice
1602660704 E [MainThread][tornado.application][web.py:1788] Uncaught exception POST /api/v2/push (<IP_ADDRESS>)
HTTPServerRequest(protocol='http', host='<IP_ADDRESS>:8801', method='POST', uri='/api/v2/push', version='HTTP/1.1', remote_ip='<IP_ADDRESS>')
Traceback (most recent call last):
File "/root/airnotifier/api/push.py", line 174, in post
self.send_response(ACCEPTED)
File "/root/airnotifier/api/init.py", line 212, in send_response
self.finish(data)
File "/root/airnotifier/api/init.py", line 215, in finish
super(APIBaseHandler, self).finish(chunk)
File "/root/.local/share/virtualenvs/airnotifier--hHQdAqd/lib64/python3.6/site-packages/tornado/web.py", line 1119, in finish
raise RuntimeError("finish() called twice")
RuntimeError: finish() called twice

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/root/.local/share/virtualenvs/airnotifier--hHQdAqd/lib64/python3.6/site-packages/tornado/web.py", line 1699, in _execute
result = await result
File "/root/airnotifier/api/push.py", line 178, in post
self.send_response(INTERNAL_SERVER_ERROR, dict(error=str(ex)))
File "/root/airnotifier/api/init.py", line 212, in send_response
self.finish(data)
File "/root/airnotifier/api/init.py", line 215, in finish
super(APIBaseHandler, self).finish(chunk)
File "/root/.local/share/virtualenvs/airnotifier--hHQdAqd/lib64/python3.6/site-packages/tornado/web.py", line 1119, in finish
raise RuntimeError("finish() called twice")
RuntimeError: finish() called twice

Access front end UI.

Go to 'voipexprod'.
Go to APNs configuration.

Remove the last character from any field.
Save.
Add character back to the field.
Save.

1602660712 I [MainThread][tornado.access][web.py:2246] 302 POST /applications/voipexprod/settings (<IP_ADDRESS>) 8.88ms
1602660712 I [MainThread][tornado.access][web.py:2246] 200 GET /applications/voipexprod/settings (<IP_ADDRESS>) 25.53ms
1602660715 I [MainThread][tornado.access][web.py:2246] 302 POST /applications/voipexprod/settings (<IP_ADDRESS>) 7.66ms
1602660715 I [MainThread][tornado.access][web.py:2246] 200 GET /applications/voipexprod/settings (<IP_ADDRESS>) 25.30ms

Make call and it works.

1602660721 I [MainThread][root][dao.py:25] find token: (<TOKEN_ID>)
1602660721 I [MainThread][root][push.py:111] sending notification to ios: (<TOKEN_ID>)
1602660722 I [MainThread][tornado.access][web.py:2246] 202 POST /api/v2/push (<IP_ADDRESS>) 922.25ms
1602660722 I [MainThread][root][init.py:218] PushHandler call ends 0.9223105907440186

1. When a rest call is made in to the service, immediately after restart, it does not work (with correct configuration).
2. Why does it take a visit to the UI to hit save to restart the connection?

Currently this activity is having to be undertaken daily to keep the service usable.

NOTE:
This issue occurs after a "104 Connection Reset by Peer" as well and requires the same change/save in the UI to make work.

Would it be possible to have a look at the above and see whether there is a resolution?
Happy to supply any additional information if required.

[dcai]

hi @Sandcrawler789 thanks for the detailed bug report, could you give me samples of your rest calls? are they ios or android push notifications?

[Sandcrawler789]

hi @dcai, thanks for the quick response.

I have attached an image below that shows the rest on the wire (it is the same in both requests). It is somewhat redacted, apologies, the tokens are correct and valid though (as it does work when kicked in UI).

Currently trying to get APNs (iOS push) working on v3.
EDIT: Sorry, I should say IT WORKS. But, it requires this change/save/change/save in UI after restart or 104 peer connection reset to get it working.

For completeness, below is attached a working rest call (202 Accepted seen).
This was done moments after the previous one (30 seconds). It is to the same host and same tokens.

[dcai]

cheers @Sandcrawler789 104 Connection Reset by Peer is this error message from rest call response, or the logs (apple apns response)?

I will look into this issue this weekend, I suspend it might something to do with server token for apple push notification service.

[Sandcrawler789]

@dcai The 104 error is from the AirNotifier logs.

I have clipped a bit of the log below (this is stdout from AirNotifier). It shows normal operation and then a 104, after this point the connection is not re-established and 32 broken pipe is seen.

This is resolved by going to the AirNotifier UI, removing the last character from any of the 4 boxes under APNs configuration. Save. Add the character back. Save.
Working again.

EDIT:
Although the same error is not seen at this point, a restart would (programmatically) be a way to fix temporarily. However, due to manual interaction in the UI this is not feasible.
There are kind of 2 issues here..

[Sandcrawler789]

Thank you for taking a look.
If any more information is required, happy to help.

[dcai]

@Sandcrawler789

I have been looking into this issue yesterday, wasn't able to reproduce it with FCM protocol (for android), I suspect this is an issue with iOS's APNS/2 protocol only, the problem is I don't have an active apple developer account to test it at the moment, Ill reach out to a friend to set it up with his account, I will update this issue when I have a test environment ready.

[Sandcrawler789]

@dcai

Unfortunately I have not got as far as testing with FCM yet, we have that working on v2 and are reluctant to move it until this one works first.
I appreciate the time taken to try and debug.

[Sandcrawler789]

Hi @dcai, wondering if you had managed to get any further with testing or found anything?

[aoisupersix]

Hi, I have a same problem with Airnotifier v3.0.
It seems that this problem occurs when FCM is not configured and only APNS is configured.

The following error occurs when starting Airnotifier:

[E 210808 20:43:22 bootstrap:40] Traceback (most recent call last):
      File "/home/workspace/moodle/airnotifier/pushservices/bootstrap.py", line 30, in init_messaging_agents
        fcminstance = FCMClient(
      File "/home/workspace/moodle/airnotifier/pushservices/fcm.py", line 30, in __init__
        jsonData = json_decode(self.jsonkey)
      File "/home/workspace/moodle/airnotifier/util.py", line 186, in json_decode
        return tornado.escape.json_decode(text)
      File "/home/.local/share/virtualenvs/airnotifier-oILszdP8/lib/python3.9/site-packages/tornado/escape.py", line 83, in json_decode
        return json.loads(to_basestring(value))
      File "/home/.pyenv/versions/3.9.6/lib/python3.9/json/__init__.py", line 346, in loads
        return _default_decoder.decode(s)
      File "/home/.pyenv/versions/3.9.6/lib/python3.9/json/decoder.py", line 337, in decode
        obj, end = self.raw_decode(s, idx=_w(s, 0).end())
      File "/home/.pyenv/versions/3.9.6/lib/python3.9/json/decoder.py", line 355, in raw_decode
        raise JSONDecodeError("Expecting value", s, err.value) from None
    json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

The cause is probably init_messaging_agents() in pushservices/bootstrap.py:

https://github.com/airnotifier/airnotifier/blob/27207bc9e8ee8f3ac9db428a456020d9e55eabda/pushservices/bootstrap.py#L28-L42

1. even if there is no FCM configuration, an empty entry is included in the app, so the FCM client is initialized
2. initialization of FCM client fails and an exception is thrown
3. The exception is caught, but the subsequent initialization process of the APNS client is skipped
4. when push notification is sent, an error occurs because there is no instance of the APNS client

Therefore, I think need to modify the code as follows:

...
        if app.get(KEY_FCM_JSON_KEY) and app.get(KEY_FCM_PROJECT_ID):
            try:
                fcminstance = FCMClient(
...