mqtt-tools / mqttwarn

A highly configurable MQTT message router, where the routing targets are notification plugins, primarily written in Python.
https://mqttwarn.readthedocs.io/
Eclipse Public License 2.0
958 stars 184 forks source link

Pushsafer, can't make it work #383

Closed jssilva25 closed 5 years ago

jssilva25 commented 5 years ago

Tried many things, the last got this message:

2019-11-15 18:37:52,278 WARNING [pushsafer] Error sending pushsafer notification to jccf [{'pr': '2', 'a': '0', 'd': '20209', 'i': '1', 'ut': 'Open Pushsafer', 'l': '60', 're': '60', 's': '', 'expire': 3600, 'u': 'http://www.pushsafer.com', 'ex': '600', 'v': '', 't': 'mqttwarn'}]:

That it has failed, I already know because it didn't reach destination. What I would like to know is how and why. But I can't find a string to pull.

I'm running mqttwarn together with mosquitto in a jail of freenas, and nothing else. My ini is:

[defaults]
hostname     = 'mqtt-server'
port         = 1883
username     = mqttuser
password     = MyObfuscatedPW
clientid     = 'mqttwarn'
lwt          = 'clients/mqttwarn'
skipretained = False
cleansession = False
libdir       = /usr/local/lib/python2.7/site-packages/mqttwarn/lib/
protocol     = 3
logformat = '%(asctime)-15s %(levelname)-5s [%(module)s] %(message)s'
logfile   = 'mqttwarn.log'
loglevel  = CRITICAL
functions = 'samplefuncs.py'
launch   = file, log, pushsafer

[config:file]
append_newline = True
targets = {
    'mylog'     : ['/tmp/mqtt.log']
    }

[config:log]
targets = {
    'info'   : [ 'info' ]
  }

[failover]
targets = log:error, file:mqttwarn

[hello/1]
targets = log:info
format = u'{name}: {number} => {_dthhmm}'

[owntracks-location]
topic = owntracks/+/+
targets = log:info, file:f01
datamap = OwnTracksTopic2Data()
format  = OwnTracksConvert()

[owntracks-battery]
topic = owntracks/+/+
targets = log:info, file:f01
datamap = OwnTracksTopic2Data()
filter  = OwnTracksBattFilter()
format  = {username}'s phone battery is getting low ({batt}%)

[robustness-1]
topic   = test/robustness-1
targets = foo:bar, log:baz

[topic-targets-dynamic]
topic   = test/topic-targets-dynamic
format  = Something {loglevel} happened! {message}
targets = log:{loglevel}

[topic-targets-func]
topic   = test/topic-targets-func
format  = Weather conditions changed: It's {condition}. Remark: {remark}
targets = TopicTargetList()

[config:pushsafer]
targets = {
    'jccf' : ['MyObfuscatedKey', '20209', '1', '', '', 'http://www.pushsafer.com', 'Open Pushsafer', '60', '2', '60', '600', '0']
    }

[maxtest]
targets = file:mylog, log:info, pushsafer:jccf

I'm insisting on Pushsafer because it looks to me the safer and best suited to my needs.

If I can make this work, it'll be most useful, thanks to the devs.

jpmens commented 5 years ago

On line 109 of the file services/pushsafer.py there is a statement

srv.logging.warn("Error sending pushsafer notification to ......

Please, before that line add a raise so that the whole thing looks like this:

except Exception, e:
        raise
        srv.logging.warn("Error sending pushsafer notification to %s [%s]: %s" % (item.target, params, str(e)))
        return False

Note that the raise is indented with spaces!

Then, please restart mqttwarn and try again; you should see a stack trace on the console. Show us that please.

jssilva25 commented 5 years ago

Thank you for your lighting fast reply!

I was sending pub command from another machine and so I thought that I needed to send it from localhost to get the stack trace but that wasn't easy and I've been struggling ever since with a "mosquitto_pub: No match" cryptic message until I just found that the freebsd version needs the pw in quotes; no references to this message anywhere on the net.

But, after inserting the raise with indent spaces guaranteed by vi, and using the -d flag on the sub and pub, I just got this:

root@mqtt-server:/ # mosquitto_pub -t "maxtest" -m "hello world" -u mqttuser -P "MyObfuscatedPw" -d
Client mosq/OnyC5dKwQewBjUzFom sending CONNECT
Client mosq/OnyC5dKwQewBjUzFom received CONNACK (0)
Client mosq/OnyC5dKwQewBjUzFom sending PUBLISH (d0, q0, r0, m1, 'maxtest', ... (11 bytes))
Client mosq/OnyC5dKwQewBjUzFom sending DISCONNECT

The log file is the same:

2019-11-16 16:09:27,886 DEBUG [mqttwarn] Job queue has 1 items to process
2019-11-16 16:09:27,886 DEBUG [mqttwarn] Processor #0 is handling: `pushsafer' for jccf
2019-11-16 16:09:27,887 DEBUG [pushsafer] *** MODULE=/usr/local/lib/python2.7/site-packages/mqttwarn/lib//services/pushsafer.py: service=pushsafer, target=jccf
2019-11-16 16:09:27,887 DEBUG [pushsafer] Sending pushsafer notification to jccf [{'pr': '2', 'a': '0', 'd': '20209', 'i': '1', 'ut': 'Open Pushsafer', 'l': '60', 're': '60', 's': '', 'expire': 3600, 'u': 'http://www.pushsafer.com', 'ex': '600', 'v': '', 't': 'mqttwarn'}]...
2019-11-16 16:09:27,888 WARNING [mqttwarn] Notification of pushsafer for `maxtest' FAILED or TIMED OUT
2019-11-16 16:09:27,888 DEBUG [mqttwarn] Job queue has 0 items to process
jpmens commented 5 years ago

(the "No match" on FreeBSD is likely due to your password containing a question mark or an asterisk; the shell you are using (csh) is trying to expand the word to a filename and finds "no match". The old joke goes like this: enter "got a light?" in the csh on that machine :-)

You don't need to send the message from localhost, just from a machine which has access to the broker. Recall that mqttwarn is subscribing to that broker; it neither cares nor knows which system the message is originating from.

So, the problem is FAILED or TIMED OUT. This appears to indicate that the service is not reacheable from the host mqttwarn is running on.

You should be able to debug that with a curl or fetch (FreeBSD I think you said)

$ curl https://www.pushsafer.com/api

$ fetch -v https://www.pushsafer.com/api

what do either of those show you?

jssilva25 commented 5 years ago

Brilliant, I'm embarrased to confess I didn't know that. Yes, my password contains both a question mark and an asterisk.

Once again, thank you for your prompt support, I'm astonished!

I'm sorry for the delay replying, walking my puppy is taking away all my available time.

So:

root@mqtt-server:/ # fetch -v https://www.pushsafer.com/api resolving server address: www.pushsafer.com:443 SSL options: 83004bff Peer verification enabled Using CA cert file: /usr/local/etc/ssl/cert.pem Verify hostname TLSv1.2 connection established using ECDHE-RSA-AES256-GCM-SHA384 Certificate subject: /OU=Domain Control Validated/OU=PositiveSSL/CN=www.pushsafer.com Certificate issuer: /C=GB/ST=Greater Manchester/L=Salford/O=COMODO CA Limited/CN=COMODO RSA Domain Validation Secure Server CA requesting https://www.pushsafer.com/api fetch: https://www.pushsafer.com/api: Unknown HTTP error

Once again you're right, my freenas (freebsd) server cannot reach pushsafer. But it goes as far as checking the certificate. Maybe any package missing? Can you please help?

EDIT: Got it through with this:

root@mqtt-server:/ # curl -s --form-string “t=Open Pushsafer” --form-string "m=hello world" --form-string "i=1” --form-string "d=20209” --form-string "k=MyObfuscatedKey" https://www.pushsafer.com/api {"status":1,"success":"message transmitted","available":48,"message_ids":"6592259:20209"}

jpmens commented 5 years ago

Did that curl invocation succeed from the machine on which mqttwarn is running? If it’s not the same box, please retry on the mqttwarn box; that’s where the issue lies.

jssilva25 commented 5 years ago

Yes, it's the same box where mqttwarn and mosquitto run, a jail in a freenas (freebsd) server, named mqtt-server.

jpmens commented 5 years ago

Try running this on that box and show me the output, please?

jpmens commented 5 years ago

Please wrap output code between two lines of three backticks ``` each.

jssilva25 commented 5 years ago

FYI had to change env python into env python2.7

{u'status': 0, u'error': u'invalid key or empty message'}

Furthermore, did tcpdump on router and no packets passed from mqtt-server with a pub; whereas with a curl, I can see the whole exchange although encrypted, includind DNS and TLS traffic. I guess this means that mqttwarn never addresses pushsafer.

jpmens commented 5 years ago

At least we know that the service can be invoked from Python from that machine.

Looking at pushsafer service module: do you have $PUSHSAFER_TOKEN configured in your environment before you launch mqttwarn?

Something along the lines of (sh/bash)

export PUSHSAFER_TOKEN=“xxx”

or (csh)

setenv PUSHSAFER_TOKEN “xxx”

The code expects it.

jssilva25 commented 5 years ago

By the way, during my tests yesterday, I change the config to:

[config:pushsafer]
targets = {
    'jccf' : ['MyObfuscatedKey', '20209', '1', '', '', '', '', '60', '2', '60', '600', '0']
  }

I guess this uses https:// instead of explicit http:// that I was using. I hope this didn't mislead you.

jssilva25 commented 5 years ago

No, I did not!

root@mqtt-server:/ # env
USER=root
LOGNAME=root
HOME=/root
MAIL=/var/mail/root
PATH=/sbin:/bin:/usr/sbin:/usr/bin:/usr/local/sbin:/usr/local/bin:/root/bin
TERM=xterm-256color
BLOCKSIZE=K
MM_CHARSET=UTF-8
LANG=en_US.UTF-8
SHELL=/bin/csh
SSH_CLIENT=192.168.1.198 53787 22
SSH_CONNECTION=192.168.1.198 53787 192.168.1.30 22
SSH_TTY=/dev/pts/1
HOSTTYPE=FreeBSD
VENDOR=amd
OSTYPE=FreeBSD
MACHTYPE=x86_64
SHLVL=2
PWD=/
GROUP=wheel
HOST=mqtt-server
REMOTEHOST=192.168.1.198
EDITOR=vi
PAGER=more

Please tell the contents for that variable.

jpmens commented 5 years ago

Strike what I said about environment, please; it’s not true.

jpmens commented 5 years ago

In your maxtest example you are using file:mylog, log:info, pushsafer:jccf

You are seeing your publishes in the mylog file and as info logging on the console, right?

jssilva25 commented 5 years ago

I'm seeing the /tmp/mqtt.log file with many lines of 'hello world'.

And I've changed log:info to log:debug. But I'm not getting any output on the mqtt-server console that issues the pub. Should I?

If necessary, I'll post the present version of mqttwarn.ini although I've already told the changes from the earlier version.

jssilva25 commented 5 years ago

If I add the -d flag, I get this:

root@mqtt-server:/ # mosquitto_pub -t maxtest -m "hello world" -u mqttuser -P "MyObfuscatedPW" -d
Client mosq/YscNKEIgIuXDdQfhhn sending CONNECT
Client mosq/YscNKEIgIuXDdQfhhn received CONNACK (0)
Client mosq/YscNKEIgIuXDdQfhhn sending PUBLISH (d0, q0, r0, m1, 'maxtest', ... (11 bytes))
Client mosq/YscNKEIgIuXDdQfhhn sending DISCONNECT
jssilva25 commented 5 years ago

If absolutely necessary, I'm willing to give you ssh root access to this jail so that you can test and fix it yourself.

jpmens commented 5 years ago

jmbp-5697

After pulling out what's left of my hair and suffering through the incredibly bad Web interface that I see at that service, I've been able to send a notification. This proves that our code works (whether it works well is up to others to say)

yyyyy is the private key.

[config:pushsafer]
'jp01' : ['yyyyy', '20370' ],
  }

[tt]
targets = log:info,pushsafer:jp01
mosquitto_pub -t tt -m hello
2019-11-17 12:00:50,489 DEBUG [pushsafer] *** MODULE=services/pushsafer.pyc: service=pushsafer, target=jp01
2019-11-17 12:00:50,490 DEBUG [pushsafer] Sending pushsafer notification to jp01 [{'expire': 3600, 'd': '20370', 't': 'mqttwarn'}]...
{'k': 'yyyyy', 'expire': 3600, 'm': u'hello', 'd': '20370', 't': 'mqttwarn'}
2019-11-17 12:00:51,967 DEBUG [pushsafer] Successfully sent pushsafer notification

Note the device in pushsafer appears to be the ID of the device, not its name.

Please create a minimal example based on mine, and test again.

jssilva25 commented 5 years ago

Yes, I just reduced the config file to the simpler form and had the same result. Yes, the ID is the device ID of Pushsafer. Still no joy.

As I wrote before, the transmission packets seem to never leave the server. Something is blocking mqttwarn to send them out. Would you please try to send them using http://, just by passing the explicit http:// url?

jpmens commented 5 years ago

Adding more than one parameter to the configuration string causes the publish to fail as it has been for you.

Please, again, test with the simpler form:

[config:pushsafer]
    'jp01' : ['yyyyy', '20370' ],
  }
jpmens commented 5 years ago

Answering your question: there's no difference between using http and https, though I would recommend against the former for security reasons. (It surprises me greatly that it's permitted at all.)

jssilva25 commented 5 years ago

I've already tested it with just k and id, with no joy, as I said just after you posted it. EDIT:

2019-11-17 13:06:05,203 DEBUG [pushsafer] Sending pushsafer notification to jccf
 [{'expire': 3600, 'd': '20209', 't': 'mqttwarn'}]...
2019-11-17 13:06:05,204 WARNING [mqttwarn] Notification of pushsafer for `maxtes
t' FAILED or TIMED OUT

The problem with https://, if you do not ask for http:// explicitly, is that I fear that mqttwarn is looking for the cert in the usual place whereas freenas, in my case, places it in /etc/ssl/cert.pem, which is a symlink to /usr/local/share/certs/ca-root-nss.crt

I would be willing to use http:// if it wouldn't work otherwise. After all, what can a pirate do, send unwanted notifications to my phone?

Would it be necessary to put the path in the config file? Or is this only required if mqttwarn accesses mosquitto with ssl and not for accessing Pushsafer?

jpmens commented 5 years ago

We ruled out HTTPS as being a problem from mqttwarn (i.e. from Python) because you successfully ran this which spoke HTTPS to pushsafer.

I'd like you to please trim down your mqttwarn.ini as far as you can. Set loglevel = DEBUG and show me the full console output you see, please.

jssilva25 commented 5 years ago

Once again, thank you for your time and extended support.

So, please tell whether this is correct:

root@mqtt-server:/usr/local/etc/mqttwarn# cat mqttwarn.ini
# -*- coding: utf-8 -*-

[defaults]
hostname     = 'mqtt-server'
port         = 1883
username     = mqttuser
password     = MyObfuscatedPW
clientid     = 'mqttwarn'
lwt          = 'clients/mqttwarn'
skipretained = False
cleansession = False
libdir       = /usr/local/lib/python2.7/site-packages/mqttwarn/lib/
protocol     = 3
logformat = '%(asctime)-15s %(levelname)-5s [%(module)s] %(message)s'
logfile   = 'mqttwarn.log'
loglevel  = DEBUG
functions = 'samplefuncs.py'
launch   = log, pushsafer

[config:log]
targets = {
    'debug'  : [ 'debug' ],
  }

; special config for 'failover' events
[failover]
targets = log:debug

[config:pushsafer]
targets = {
    'jccf' : ['MyObfuscatedKey', '20209'],
  }

[maxtest]
targets = log:debug, pushsafer:jccf

mqttwarn.log:

2019-11-17 15:18:47,447 DEBUG [pushsafer] Sending pushsafer notification to jccf
 [{'expire': 3600, 'd': '20209', 't': 'mqttwarn'}]...
2019-11-17 15:18:47,448 WARNING [mqttwarn] Notification of pushsafer for `maxtes
t' FAILED or TIMED OUT

Console:

root@mqtt-server:/ # mosquitto_pub -t maxtest -m "hello world" -u mqttuser -P "MyObfuscatedPW" -d
Client mosq/4Bq8IaTeZsrmuicKd0 sending CONNECT
Client mosq/4Bq8IaTeZsrmuicKd0 received CONNACK (0)
Client mosq/4Bq8IaTeZsrmuicKd0 sending PUBLISH (d0, q0, r0, m1, 'maxtest', ... (11 bytes))
Client mosq/4Bq8IaTeZsrmuicKd0 sending DISCONNECT
jpmens commented 5 years ago

That looks ok to me, and I don’t see any difference between your test and my test other than that yours doesn’t work. #sigh We know for a fact that your FreeBSD box can access the service (you verified that here), and you’ve whittled your configuration down to the minimum required by the service.

You know your data (key, deviceID) are correct because you posted a message using curl. We also know the code mqttwarn is using works, because it worked here for me, and it is not producing a stack trace.

You are probably starting to see what this is leading to ...

Due to the missing stack trace, it must be due to some value that’s incorrect from the point of view Pushsafer. I assume you have quadruple-checked your key and your device number.

If so: ... I’m going to give up. I’ve spent far too much time on this.

My recommendation to you is to try one of the other notification services, see whether there’s one which works for you.

Be that as it may, I’m sorry. I just don’t see what’s wrong with your setup.

jssilva25 commented 5 years ago

I fully understand, agree and thank you for your extended time.

What is still puzzling me is that tcpdump didn't catch any traffic leaving the server with the pub method, whereas it caught a lot of traffic with the curl method, although obviously encrypted. This leads me to believe that Pushsafer is not to blame, it doesn't even get the request.

I'm targeting Pushsafer because I guess it is the safer, simple and eventually reliable push service that I investigated. If you think there's a better suited, and working, service, by all means please advise.

jpmens commented 5 years ago

One last try: on after this line, please add

print(data)

correctly indented (the print under ‘data’) and restart mqttwarn. Keep an eye on the console please and show me the output you get.

jssilva25 commented 5 years ago
root@mqtt-server:/ # mosquitto_pub -t maxtest -m "hello world" -u mqttuser -P "MyObfuscatedPW" -d
Client mosq/nAKhGbTp97wadKiwa5 sending CONNECT
Client mosq/nAKhGbTp97wadKiwa5 received CONNACK (0)
Client mosq/nAKhGbTp97wadKiwa5 sending PUBLISH (d0, q0, r0, m1, 'maxtest', ... (11 bytes))
Client mosq/nAKhGbTp97wadKiwa5 sending DISCONNECT

Why am I not getting console output from mqttwarn (python)? The above output seems to be from mosquitto_pub only. My shell is csh and I'm accessing through ssh, if that matters. Anyway, the env was posted above.

jpmens commented 5 years ago

We don’’t need mosquitto_pub output; we know that’s working.

You need to stop mqttwarn and start it from your shell. You then publish your value and you should then see mqttwarn print data to the console.

jssilva25 commented 5 years ago

I did restart mqttwarn with:

root@mqtt-server:/ # service supervisord restart
Stopping supervisord.
Waiting for PIDS: 69034.
Starting supervisord.
root@mqtt-server:/ # mosquitto_pub -t maxtest -m "hello world" -u mqttuser -P "MyObfuscatedPW" -d
Client mosq/nAKhGbTp97wadKiwa5 sending CONNECT
Client mosq/nAKhGbTp97wadKiwa5 received CONNACK (0)
Client mosq/nAKhGbTp97wadKiwa5 sending PUBLISH (d0, q0, r0, m1, 'maxtest', ... (11 bytes))
Client mosq/nAKhGbTp97wadKiwa5 sending DISCONNECT
jpmens commented 5 years ago

You keep showing me the output of your mosquitto_pub command; I’m not interested in that. :)

OK, then show me the mqttwarn.log please starting at the time of its last restart.

jssilva25 commented 5 years ago

So, when you say console, which one do you mean, once it is not the one I use to issue the mosquitto_pub?

mqttwarn.log

2019-11-17 17:02:12,569 DEBUG [mqttwarn] Disconnecting from MQTT broker...
2019-11-17 17:02:12,569 INFO  [mqttwarn] Clean disconnection from broker
2019-11-17 17:02:12,569 INFO  [mqttwarn] Waiting for queue to drain
2019-11-17 17:02:12,569 DEBUG [mqttwarn] Exiting on signal 15
2019-11-17 17:02:13,794 INFO  [mqttwarn] Starting mqttwarn
2019-11-17 17:02:13,794 INFO  [mqttwarn] Log level is DEBUG
2019-11-17 17:02:13,795 DEBUG [mqttwarn] Service log loaded
2019-11-17 17:02:13,800 DEBUG [mqttwarn] Service pushsafer loaded
2019-11-17 17:02:13,800 DEBUG [mqttwarn] Attempting connection to MQTT broker mqtt-server:1883...
2019-11-17 17:02:13,800 DEBUG [mqttwarn] Setting LWT to clients/mqttwarn...
2019-11-17 17:02:13,801 INFO  [mqttwarn] Starting 1 worker threads
2019-11-17 17:02:13,801 DEBUG [mqttwarn] Job queue has 0 items to process
2019-11-17 17:02:13,801 DEBUG [mqttwarn] Connected to MQTT broker, subscribing to topics...
2019-11-17 17:02:13,801 DEBUG [mqttwarn] Cleansession==False; previous subscriptions for clientid mqttwarn remain active on broker
2019-11-17 17:02:13,802 DEBUG [mqttwarn] Subscribing to maxtest (qos=0)
2019-11-17 17:02:25,753 DEBUG [mqttwarn] Message received on maxtest: hello world
2019-11-17 17:02:25,753 DEBUG [mqttwarn] Section [maxtest] matches message on maxtest. Processing...
2019-11-17 17:02:25,754 DEBUG [mqttwarn] Cannot decode JSON object, payload=hello world: No JSON object could be decoded
2019-11-17 17:02:25,754 DEBUG [mqttwarn] Message on maxtest going to log:debug
2019-11-17 17:02:25,754 DEBUG [mqttwarn] New `log:debug' job: maxtest
2019-11-17 17:02:25,754 DEBUG [mqttwarn] Message on maxtest going to pushsafer:jccf
2019-11-17 17:02:25,754 DEBUG [mqttwarn] New `pushsafer:jccf' job: maxtest
2019-11-17 17:02:25,754 DEBUG [mqttwarn] Processor #0 is handling: `log' for debug
2019-11-17 17:02:25,755 DEBUG [log] *** MODULE=/usr/local/lib/python2.7/site-packages/mqttwarn/lib//services/log.pyc: service=log, target=debug
2019-11-17 17:02:25,755 DEBUG [log] hello world
2019-11-17 17:02:25,756 DEBUG [mqttwarn] Job queue has 1 items to process
2019-11-17 17:02:25,756 DEBUG [mqttwarn] Processor #0 is handling: `pushsafer' for jccf
2019-11-17 17:02:25,756 DEBUG [pushsafer] *** MODULE=/usr/local/lib/python2.7/site-packages/mqttwarn/lib//services/pushsafer.py: service=pushsafer, target=jccf
2019-11-17 17:02:25,756 DEBUG [pushsafer] Sending pushsafer notification to jccf [{'expire': 3600, 'd': '20209', 't': 'mqttwarn'}]...
2019-11-17 17:02:25,757 WARNING [mqttwarn] Notification of pushsafer for `maxtest' FAILED or TIMED OUT
2019-11-17 17:02:25,758 DEBUG [mqttwarn] Job queue has 0 items to process
jssilva25 commented 5 years ago

Would you please ssh log into the server to look for yourself? I could send you the login details by email.

jssilva25 commented 5 years ago

Just sent the login details by gmail.

jpmens commented 5 years ago

No, sorry; I won’t do that. That’s taking open source support (free) a tad too far.

jssilva25 commented 5 years ago

Right, I understand. Thank you anyway.

jssilva25 commented 5 years ago

I'll have to walk my Akita Inu puppy now, otherwise he will pee in my room.

jpmens commented 5 years ago

I know how it feels. :)

  1. Stop mqttwarn with service supervisord stop
  2. Determine how mqttwarn is started from within supervisord. Something like grep mqttwarn.py /usr/local/etc/supervisord.d/* (be a bit generous with the paths; I don’t know how it’s installed there)
  3. You’ll have found a command which resembles /usr/local/bin/mqttwarn.py mqttwar.ini or something similar. That’s how you will, in a moment, launch it.
  4. Ensure you added the print(data) statement after line 25 of the service file
  5. Launch mqttwarn with the command you found at 3. earlier
  6. Publish your message with mosquitto_pub from a different window (log in again if need be)

You should now see somewhere a rather messy output with data. That ought to be the result of the submission to Pushsafer. Show me that please.

If you need to, hit CTL-C to kill mqttwarn. You can then restart it via supervisord if you want to return to “normality”.

jssilva25 commented 5 years ago

Just got back, he liked the walk :) Now I get it; of course I couldn't get console output. At the moment I'm having a struggle with program launching; just found /usr/local/etc/supervisord/mqttwarn.conf with the right program launch and environment variables. Will post as soon as solved.

jssilva25 commented 5 years ago

This is really puzzling. Based on mqttwarn.conf, I stopped supervisord and started mqttwarn:

root@mqtt-server:/ # sudo -u mqttwarn env MQTTWARNINI="/usr/local/etc/mqttwarn/mqttwarn.ini" MQTTWARNLOG="/var/log/mqttwarn/mqttwarn.log"  /usr/local/sbin/mqttwarn

And assured that it had in fact started, on another console:

root@mqtt-server:/ # ps axuw | grep mqttwarn
root     90064  0.0  0.0  8092  4464  0  I+J  19:33   0:00.00 sudo -u mqttwarn env MQTTWARNINI=/usr/local/etc/mqttwarn/mqttwarn.ini
mqttwarn 90065  0.0  0.1 25532 17040  0  S+J  19:33   0:00.08 /usr/local/bin/python2.7 /usr/local/sbin/mqttwarn
root     90497  0.0  0.0  6740  2640  1  S+J  19:38   0:00.00 grep mqttwarn

Then fired mosquitto_pub on another console:

root@mqtt-server:/ # mosquitto_pub -t maxtest -m "hello world" -u mqttuser -P "ObfuscatedPW" -d
Client mosq/gAqRmTtjK8cazj6RiK sending CONNECT
Client mosq/gAqRmTtjK8cazj6RiK received CONNACK (0)
Client mosq/gAqRmTtjK8cazj6RiK sending PUBLISH (d0, q0, r0, m1, 'maxtest', ... (11 bytes))
Client mosq/gAqRmTtjK8cazj6RiK sending DISCONNECT

But still no output on the first console where mqttwarn was launched. The addings "raise" and "print(data)" are in place. I also renamed pushsafer.pyc to old, just to be on the safe side, and a new one was compiled. Log result is the same. This is really mind-breaking.

jpmens commented 5 years ago

which pushsafer.py file did you modify? Please insert a syntax error (a arbitrary line containing asdf should suffice) to ensure that the module raises an error when you publish your MQTT payload. Then start mqttwarn and publish your payload.

There is really no need to show me this MQTT publish at each time:

root@mqtt-server:/ # mosquitto_pub -t maxtest -m "hello world" -u mqttuser -P "ObfuscatedPW" -d

jssilva25 commented 5 years ago

I changed /usr/local/lib/python2.7/site-packages/mqttwarn/lib/services/pushsafer.py So, I inserted a line containing asdf immediately after the print(data) line that I had inserted before. Then started:

sudo -u mqttwarn env MQTTWARNINI="/usr/local/etc/mqttwarnqttwarn.ini" MQTTWARNLOG="/var/log/mqttwarn/mqttwarn.log" /usr/local/sbin/mqttwarn

and published. There was no error message at the console, neither at the log. Then I made a full scan searching for pushsafer that only found pushsafer.py, pushsafer.pyc and the original versions that I had saved.

jpmens commented 5 years ago

You are going to have to print() your way through pushsafer.py; if it doesn't trigger at line 25, then it bails out earlier, though no idea why.

Start at somewhere around line 39, within the plugin() function. I would add

print("HELLO-JSSILVA-001--------")

or something you can easily detect on the console.

Then a bit further down in the file, just before and after

pushsafer(m=message, k=appkey, **params)

again, watch out to use only spaces for indentation.

jssilva25 commented 5 years ago

Finally some reaction. It does print messages 1 and 2, but not #3 after pushsafer(...) Still does not syntax error caused by asdf after print(data)

jpmens commented 5 years ago

Please replace or comment out (prefix each line with #)

    try:
        srv.logging.debug("Sending pushsafer notification to %s [%s]..." % (item.target, params))
        pushsafer(m=message, k=appkey, **params)
        srv.logging.debug("Successfully sent pushsafer notification")
    except Exception, e:
        srv.logging.warn("Error sending pushsafer notification to %s [%s]: %s" % (item.target, params, str(e)))
        return False

by

pushsafer(m=message, k=appkey, **params)

That last line must be at the level of the original try line.

jssilva25 commented 5 years ago

Only test message 1 printed, the others were commented out. No change at the log, meaning usual FAILED

jpmens commented 5 years ago

the log won't change; the output on the console (i.e. stdout) will. Should. MUST.

jssilva25 commented 5 years ago

Sorry, didn't.

#    try:
#        srv.logging.debug("Sending pushsafer notification to %s [%s]..." % (ite
#        print("HELLO-JSSILVA-002--------")
#        pushsafer(m=message, k=appkey, **params)
#        print("HELLO-JSSILVA-003--------")
#        srv.logging.debug("Successfully sent pushsafer notification")
#    except Exception, e:
#        raise
#        srv.logging.warn("Error sending pushsafer notification to %s [%s]: %s"
#        return False
    pushsafer(m=message, k=appkey, **params)

    return True
root@mqtt-server:/ # sudo -u mqttwarn env MQTTWARNINI="/usr/local/etc/mqttwarnqttwarn.ini" MQTTWARNLOG="/var/log/mqttwarn/mqttwarn.log" /usr/local/sbin/mqttwarn
HELLO-JSSILVA-001--------
jssilva25 commented 5 years ago

I wonder if this is relevant: I've just placed a print() inside pushsafer() and it doesn't print. Furthermore, the asdf line does not produce syntax error. Is then pushsafer() being called at all?

jssilva25 commented 5 years ago

It does print as long as I put it at the top, before:

    assert 'message' in kwargs

EDIT: Double-checked