search

openhab / openhab1-addons

Add-ons for openHAB 1.x
Eclipse Public License 2.0
3.43k stars 1.7k forks source link

[Telegram] photoURL does not represent a known image type #5254

Closed MrMontesa closed 7 years ago

MrMontesa commented 7 years ago

Expected Behavior

I'm running Motioneye software on a Pi Zero W with the NoIR cam. The software has the option to curl images and use them right away. The link looks like this: http://192.168.23.17:8765/picture/1/current/?_username=admin&_signature=$my_security_token

I want to use this URL in rules using the sendTelegramPhoto function. My rule code looks like this:

val String url = "http://192.168.23.17:8765/picture/1/current/?_username=admin&_signature=$my_security_token"
logInfo("SecCam", "URL: " + url)
 sendTelegramPhoto("bot1", url,"Groundfloor Cam")

This should send the photo via Telegram.

Current Behavior

Unfortunately the above rule spits an error:

2017-07-17 10:33:19.366 [INFO ] [clipse.smarthome.model.script.SecCam] - URL: http://192.168.23.17:8765/picture/1/current/?_username=admin&_signature=$my_security_token
2017-07-17 10:33:19.406 [ERROR] [ab.action.telegram.internal.Telegram] - photoURL does not represent a known image type

Since I can properly curl the image using the url I'm quite sure motioneye works ok. Is it possible that Openhab has issues finding the image? I'm not 100% sure, but I think I was running this functionlatiy before on OH2.0. Since my PiZero setup broke I never activated it for production use. Now on OH 2.1 and fixed PiZero I'd like to start again. Also opened a dicussion at community.openhab.org

Possible Solution

Since this is very much hardware (PiZero) & software (motioneye) related, I know its difficult to reproduce. Possibly we can focus on the what leads to this error message and understand why OH behaves the way it does. The motioneye software is also hosted on github and we might have a chat with the developer as well.

Steps to Reproduce (for Bugs)

  1. get Pi with Cam
  2. Install & configure motioneye
  3. Install Telegram Binding
  4. write rule using motioneye link

Context

I have several webcams around the house acting as a security system. In case motion is detetected by some PIRs, I'd like to send telegram messages containing the webcam image. This nicely works with all IP cams I have querying the CGI interface of the webcams, but doesnt work with motioneye and PiZero cam.

Your Environment

OH 2.1 release build with Telegram binding PiZero W with NoIR cam running debian 7 and motionEye 0.35.2

sjsf commented 7 years ago

Would you happen to have an example image returned by motioneye which you can attach here? Maybe that would help the developers analyzing the issue better as the required setup to reproduce it seems to be quite specific. I'd assume there is something about the file format which makes it choke on.

Of course it does not matter what exactly on the picture is, just hold something in front of your camera or let it face the wall - i.e. don't publish your home here in the internet.

MrMontesa commented 7 years ago

Here's a photo I curl'ed. Source was openhab server connectin against the motioneye installation running on the Pi zero. swa

Heres the curl command and output I used:

swa@nuc:/tmp $ curl -m 10 -o /tmp/swa.jpg 'http://192.168.23.17:8765/picture/1/current/?_username=admin&_signature=$my_token'
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 28410  100 28410    0     0   239k      0 --:--:-- --:--:-- --:--:--  241k
swa@nuc:/tmp $ ls -al /tmp/swa.jpg
-rw-r--r--  1 swa  swa  28410 Jul 20 13:37 swa.jpg

Let me know in case I could be of any help troubleshooting this issue in more depth. And thanks for your help

9037568 commented 7 years ago

Can you get an md5 checksum of the file?

I tried parsing your image locally and it was correctly identified:

X:\java>java checkImageType http://localhost:8080/images/28415706-271a784e-6d51-11e7-88f3-5155ededfc91.jpg
Image type: JPEG

Also, you should try running your curl as the same user that openhab runs as to verify there's no user/permissions problem involved.

And then if you're still seeing the error, try capturing a debug log for analysis.

MrMontesa commented 7 years ago

Hey, unfortunately the image from above is already gone. If needed, I could upload another one to confirm.

I also tried your java command on my local box and got an error that main class checkImageType was not found. Is JSE sufficient or do I need SDK for that?

I'm aware of the user priviledges. I wrote a small script that curls the image and places it in Openhabs /static/ folder. From there the sendTelegramPhoto pics it. This is running properly as openhab user. The only thing I recognized while scripting this, was that curl sometimes exits with ok, but doesnt download anything. When sleeping 2 seconds and trying again, it perfectly works. Also discussing this with the motioneye devs.

I reproduces the error in DEBUG. Here's the log:

2017-07-21 09:57:47.607 [DEBUG] [.httpclient.params.DefaultHttpParams] - Set parameter http.socket.timeout = 10000
2017-07-21 09:57:47.608 [DEBUG] [.httpclient.params.DefaultHttpParams] - Set parameter http.method.retry-handler = org.apache.commons.httpclient.DefaultHttpMeth                               odRetryHandler@5a8dc467
2017-07-21 09:57:47.609 [DEBUG] [he.commons.httpclient.HttpConnection] - Open connection to 192.168.23.17:8765
2017-07-21 09:57:47.616 [DEBUG] [httpclient.wire.header              ] - >> "GET /picture/1/current/?_username=admin&_signature=$my_token                               28575689 HTTP/1.1[\r][\n]"
2017-07-21 09:57:47.617 [DEBUG] [he.commons.httpclient.HttpMethodBase] - Adding Host request header
2017-07-21 09:57:47.618 [DEBUG] [httpclient.wire.header              ] - >> "User-Agent: Jakarta Commons-HttpClient/3.1[\r][\n]"
2017-07-21 09:57:47.618 [DEBUG] [httpclient.wire.header              ] - >> "Host: 192.168.23.17:8765[\r][\n]"
2017-07-21 09:57:47.618 [DEBUG] [httpclient.wire.header              ] - >> "[\r][\n]"
2017-07-21 09:57:47.639 [DEBUG] [httpclient.wire.header              ] - << "HTTP/1.1 200 OK[\r][\n]"
2017-07-21 09:57:47.640 [DEBUG] [httpclient.wire.header              ] - << "HTTP/1.1 200 OK[\r][\n]"
2017-07-21 09:57:47.640 [DEBUG] [httpclient.wire.header              ] - << "Content-Length: 0[\r][\n]"
2017-07-21 09:57:47.640 [DEBUG] [httpclient.wire.header              ] - << "Set-Cookie: motion_detected_1=false; Path=/[\r][\n]"
2017-07-21 09:57:47.640 [DEBUG] [httpclient.wire.header              ] - << "Set-Cookie: monitor_info_1=; Path=/[\r][\n]"
2017-07-21 09:57:47.640 [DEBUG] [httpclient.wire.header              ] - << "Set-Cookie: capture_fps_1=0.0; Path=/[\r][\n]"
2017-07-21 09:57:47.640 [DEBUG] [httpclient.wire.header              ] - << "Server: motionEye/0.35.2[\r][\n]"
2017-07-21 09:57:47.640 [DEBUG] [httpclient.wire.header              ] - << "Etag: "da39a3ee5e6b4b0d3255bfef95601890afd80709"[\r][\n]"
2017-07-21 09:57:47.640 [DEBUG] [httpclient.wire.header              ] - << "Date: Fri, 21 Jul 2017 07:57:01 GMT[\r][\n]"
2017-07-21 09:57:47.641 [DEBUG] [httpclient.wire.header              ] - << "Content-Type: image/jpeg[\r][\n]"
2017-07-21 09:57:47.641 [DEBUG] [httpclient.wire.header              ] - << "[\r][\n]"
2017-07-21 09:57:47.642 [DEBUG] [he.commons.httpclient.HttpMethodBase] - Cookie accepted: "$Version=0; motion_detected_1=false; $Path=/"
2017-07-21 09:57:47.642 [DEBUG] [he.commons.httpclient.HttpMethodBase] - Cookie accepted: "$Version=0; monitor_info_1=; $Path=/"
2017-07-21 09:57:47.643 [DEBUG] [he.commons.httpclient.HttpMethodBase] - Cookie accepted: "$Version=0; capture_fps_1=0.0; $Path=/"
2017-07-21 09:57:47.643 [DEBUG] [he.commons.httpclient.HttpMethodBase] - Buffering response body
2017-07-21 09:57:47.643 [DEBUG] [he.commons.httpclient.HttpMethodBase] - Resorting to protocol version default close connection policy
2017-07-21 09:57:47.644 [DEBUG] [he.commons.httpclient.HttpMethodBase] - Should NOT close connection, using HTTP/1.1
2017-07-21 09:57:47.644 [DEBUG] [he.commons.httpclient.HttpConnection] - Releasing connection back to connection manager.
2017-07-21 09:57:47.645 [ERROR] [ab.action.telegram.internal.Telegram] - photoURL does not represent a known image type
9037568 commented 7 years ago

Yeah, sorry. checkImageType was just a little throwaway program I wrote to try parsing an image using the same underlying library as the OH Telegram uses.

I wonder if we need a config option to force an image type when it can't be determined.

Here's a test jar that outputs the first 24 bytes of the image stream as a debug message when the type check fails.

MrMontesa commented 7 years ago

Thanks for looking into this. I uninstalled the release addon and installed your snap.

 2017-07-21 14:10:56.942 [INFO ] [core.karaf.internal.FeatureInstaller] - Uninstalled 'openhab-action-telegram'
 2017-07-21 14:11:33.610 [INFO ] [org.apache.felix.fileinstall        ] - Installing bundle org.openhab.action.telegram / 1.11.0.201707211142
 2017-07-21 14:11:33.796 [INFO ] [egram.internal.TelegramActionService] - Bot sepp loaded from config file
 2017-07-21 14:11:33.977 [INFO ] [egram.internal.TelegramActionService] - Bot gruppe loaded from config file
 2017-07-21 14:11:33.986 [INFO ] [org.apache.felix.fileinstall        ] - Started bundle: file:/usr/share/openhab2/addons/org.openhab.action.telegram-1.11.0-SNAPSHOT.jar

Here's a recent DEBUG log. Hope it helps.

2017-07-21 14:15:30.994 [DEBUG] [.httpclient.params.DefaultHttpParams] - Set parameter http.socket.timeout = 10000
2017-07-21 14:15:30.994 [DEBUG] [clipse.jetty.server.HttpChannelState] - HttpChannelState@38eeeab2{s=DISPATCHED i=true a=null} unhandle DISPATCHED
2017-07-21 14:15:30.995 [DEBUG] [.httpclient.params.DefaultHttpParams] - Set parameter http.method.retry-handler = org.apache.commons.httpclient.DefaultHttpMethodRetryHandler@4eb001cf
2017-07-21 14:15:30.995 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@509eee02[PROCESSING][i=ResponseInfo{HTTP/1.1 202 Accepted,-1,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5701a3c6] generate: NEED_HEADER (null,[p=0,l=0,c=0,r=0],true)@START
2017-07-21 14:15:30.996 [DEBUG] [he.commons.httpclient.HttpConnection] - Open connection to 192.168.23.17:8765
2017-07-21 14:15:30.997 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@509eee02[PROCESSING][i=ResponseInfo{HTTP/1.1 202 Accepted,-1,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5701a3c6] generate: FLUSH ([p=0,l=146,c=8192,r=146],[p=0,l=0,c=0,r=0],true)@COMPLETING
2017-07-21 14:15:30.998 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - flushed 149 SelectChannelEndPoint@2a2376f4{/80.152.160.250:44118<->8080,Open,in,out,-,W,9488/30000,HttpConnection}{io=0,kio=0,kro=1}
2017-07-21 14:15:31.000 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@47d9e266[PROCESSING][i=null,cb=Blocker@48b10aca{null}] generate: DONE (null,[p=143,l=143,c=32768,r=0],false)@COMMITTED
2017-07-21 14:15:31.001 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@463ddb34[PROCESSING][i=null,cb=Blocker@6f9570db{null}] generate: FLUSH (null,[p=0,l=143,c=32768,r=143],false)@COMMITTED
2017-07-21 14:15:31.002 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - flushed 149 SelectChannelEndPoint@72ba5485{/192.168.23.133:54781<->8080,Open,in,out,-,W,9493/30000,HttpConnection}{io=0,kio=0,kro=1}
2017-07-21 14:15:31.003 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@463ddb34[PROCESSING][i=null,cb=Blocker@6f9570db{null}] generate: DONE (null,[p=143,l=143,c=32768,r=0],false)@COMMITTED
2017-07-21 14:15:31.003 [DEBUG] [httpclient.wire.header              ] - >> "GET /picture/1/current/?_username=admin&_signature=$my_token HTTP/1.1[\r][\n]"
2017-07-21 14:15:31.004 [DEBUG] [he.commons.httpclient.HttpMethodBase] - Adding Host request header
2017-07-21 14:15:31.004 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@47d9e266[PROCESSING][i=null,cb=Blocker@48b10aca{null}] generate: FLUSH (null,[p=0,l=199,c=32768,r=199],false)@COMMITTED
2017-07-21 14:15:31.005 [DEBUG] [httpclient.wire.header              ] - >> "User-Agent: Jakarta Commons-HttpClient/3.1[\r][\n]"
2017-07-21 14:15:31.006 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - flushed 205 SelectChannelEndPoint@2a2376f4{/80.152.160.250:44118<->8080,Open,in,out,-,W,5/30000,HttpConnection}{io=0,kio=0,kro=1}
2017-07-21 14:15:31.006 [DEBUG] [httpclient.wire.header              ] - >> "Host: 192.168.23.17:8765[\r][\n]"
2017-07-21 14:15:31.007 [DEBUG] [httpclient.wire.header              ] - >> "[\r][\n]"
2017-07-21 14:15:31.007 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@47d9e266[PROCESSING][i=null,cb=Blocker@48b10aca{null}] generate: DONE (null,[p=199,l=199,c=32768,r=0],false)@COMMITTED
2017-07-21 14:15:31.009 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - flushed 146 SelectChannelEndPoint@c912c82{/0:0:0:0:0:0:0:1:59432<->8080,Open,in,out,-,W,86/30000,HttpConnection}{io=0,kio=0,kro=1}
2017-07-21 14:15:31.015 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@509eee02[PROCESSING][i=ResponseInfo{HTTP/1.1 202 Accepted,-1,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@5701a3c6] generate: DONE ([p=146,l=146,c=8192,r=0],[p=0,l=0,c=0,r=0],true)@END
2017-07-21 14:15:31.017 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - reset HttpParser{s=END,3 of 3}
2017-07-21 14:15:31.012 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@463ddb34[PROCESSING][i=null,cb=Blocker@6f9570db{null}] generate: FLUSH (null,[p=0,l=199,c=32768,r=199],false)@COMMITTED
2017-07-21 14:15:31.019 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - flushed 205 SelectChannelEndPoint@72ba5485{/192.168.23.133:54781<->8080,Open,in,out,-,W,15/30000,HttpConnection}{io=0,kio=0,kro=1}
2017-07-21 14:15:31.020 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@463ddb34[PROCESSING][i=null,cb=Blocker@6f9570db{null}] generate: DONE (null,[p=199,l=199,c=32768,r=0],false)@COMMITTED
2017-07-21 14:15:31.021 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - END --> START
2017-07-21 14:15:31.023 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - HttpChannelOverHttp@649360d8{r=1,c=false,a=IDLE,uri=} handle exit, result COMPLETE
2017-07-21 14:15:31.025 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - filled -1 SelectChannelEndPoint@c912c82{/0:0:0:0:0:0:0:1:59432<->8080,Open,in,out,-,-,10/30000,HttpConnection}{io=0,kio=0,kro=1}
2017-07-21 14:15:31.027 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - ishut SelectChannelEndPoint@c912c82{/0:0:0:0:0:0:0:1:59432<->8080,Open,in,out,-,-,11/30000,HttpConnection}{io=0,kio=0,kro=1}
2017-07-21 14:15:31.028 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - atEOF HttpParser{s=START,0 of -1}
2017-07-21 14:15:31.030 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - parseNext s=START HeapByteBuffer@68d8ed6f[p=0,l=0,c=8192,r=0]={<<<>>>HTTP/1.1 200 OK\r\n...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2017-07-21 14:15:31.031 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - START --> CLOSED
2017-07-21 14:15:31.033 [DEBUG] [rg.eclipse.jetty.io.AbstractEndPoint] - onClose SelectChannelEndPoint@c912c82{/0:0:0:0:0:0:0:1:59432<->8080,CLOSED,ISHUT,out,-,-,17/30000,HttpConnection}{io=0,kio=0,kro=1}
2017-07-21 14:15:31.034 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - close SelectChannelEndPoint@c912c82{/0:0:0:0:0:0:0:1:59432<->8080,CLOSED,ISHUT,out,-,-,19/30000,HttpConnection}{io=0,kio=0,kro=1}
2017-07-21 14:15:31.036 [DEBUG] [org.eclipse.jetty.io.SelectorManager] - Destroyed SelectChannelEndPoint@c912c82{/0:0:0:0:0:0:0:1:59432<->8080,CLOSED,ISHUT,OSHUT,-,-,21/30000,HttpConnection}{io=0,kio=-1,kro=-1}
2017-07-21 14:15:31.038 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - onClose HttpConnection@32f64970[FILLING,SelectChannelEndPoint@c912c82{/0:0:0:0:0:0:0:1:59432<->8080,CLOSED,ISHUT,OSHUT,-,-,22/30000,HttpConnection}{io=0,kio=-1,kro=-1}][p=HttpParser{s=CLOSED,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@649360d8{r=1,c=false,a=IDLE,uri=}]
2017-07-21 14:15:31.040 [DEBUG] [rg.eclipse.jetty.io.AbstractEndPoint] - onClose SelectChannelEndPoint@c912c82{/0:0:0:0:0:0:0:1:59432<->8080,CLOSED,ISHUT,OSHUT,-,-,24/30000,HttpConnection}{io=0,kio=-1,kro=-1}
2017-07-21 14:15:31.041 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - FILLING-->IDLE HttpConnection@32f64970[IDLE,SelectChannelEndPoint@c912c82{/0:0:0:0:0:0:0:1:59432<->8080,CLOSED,ISHUT,OSHUT,-,-,26/30000,HttpConnection}{io=0,kio=-1,kro=-1}][p=HttpParser{s=CLOSED,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@649360d8{r=1,c=false,a=IDLE,uri=}]
2017-07-21 14:15:31.065 [DEBUG] [httpclient.wire.header              ] - << "HTTP/1.1 200 OK[\r][\n]"
2017-07-21 14:15:31.065 [DEBUG] [httpclient.wire.header              ] - << "HTTP/1.1 200 OK[\r][\n]"
2017-07-21 14:15:31.066 [DEBUG] [httpclient.wire.header              ] - << "Content-Length: 0[\r][\n]"
2017-07-21 14:15:31.066 [DEBUG] [httpclient.wire.header              ] - << "Set-Cookie: motion_detected_1=false; Path=/[\r][\n]"
2017-07-21 14:15:31.067 [DEBUG] [httpclient.wire.header              ] - << "Set-Cookie: monitor_info_1=; Path=/[\r][\n]"
2017-07-21 14:15:31.067 [DEBUG] [httpclient.wire.header              ] - << "Set-Cookie: capture_fps_1=0.0; Path=/[\r][\n]"
2017-07-21 14:15:31.067 [DEBUG] [httpclient.wire.header              ] - << "Server: motionEye/0.35.2[\r][\n]"
2017-07-21 14:15:31.067 [DEBUG] [httpclient.wire.header              ] - << "Etag: "da39a3ee5e6b4b0d3255bfef95601890afd80709"[\r][\n]"
2017-07-21 14:15:31.067 [DEBUG] [httpclient.wire.header              ] - << "Date: Fri, 21 Jul 2017 12:14:44 GMT[\r][\n]"
2017-07-21 14:15:31.067 [DEBUG] [httpclient.wire.header              ] - << "Content-Type: image/jpeg[\r][\n]"
2017-07-21 14:15:31.068 [DEBUG] [httpclient.wire.header              ] - << "[\r][\n]"
2017-07-21 14:15:31.068 [DEBUG] [he.commons.httpclient.HttpMethodBase] - Cookie accepted: "$Version=0; motion_detected_1=false; $Path=/"
2017-07-21 14:15:31.068 [DEBUG] [he.commons.httpclient.HttpMethodBase] - Cookie accepted: "$Version=0; monitor_info_1=; $Path=/"
2017-07-21 14:15:31.069 [DEBUG] [he.commons.httpclient.HttpMethodBase] - Cookie accepted: "$Version=0; capture_fps_1=0.0; $Path=/"
2017-07-21 14:15:31.069 [DEBUG] [he.commons.httpclient.HttpMethodBase] - Buffering response body
2017-07-21 14:15:31.069 [DEBUG] [he.commons.httpclient.HttpMethodBase] - Resorting to protocol version default close connection policy
2017-07-21 14:15:31.069 [DEBUG] [he.commons.httpclient.HttpMethodBase] - Should NOT close connection, using HTTP/1.1
2017-07-21 14:15:31.070 [DEBUG] [he.commons.httpclient.HttpConnection] - Releasing connection back to connection manager.
2017-07-21 14:15:31.071 [ERROR] [ab.action.telegram.internal.Telegram] - photoURL does not represent a known image type
9037568 commented 7 years ago

This line is interesting:

2017-07-21 14:15:31.066 [DEBUG] [httpclient.wire.header              ] - << "Content-Length: 0[\r][\n]"

Also, it looks like you either didn't get DEBUG logging enabled for the Telegram package, or OH is still running the old version of the package.

You should have gotten a new DEBUG message before the error and a new one after it, like so:

[DEBUG] ... imageInputStream length: <integer value here>
[ERROR] ... photoURL does not represent a known image type
[DEBUG] ... first 24 bytes: ...
9037568 commented 7 years ago

It may also be time to get old-school and do a network trace.

MrMontesa commented 7 years ago

I restarted OH to make sure the SNAPSHOT addon is the active one. Here some commands from the console:

openhab> log:get
Logger | Level
--------------
ROOT   | INFO
openhab> log:set DEBUG
openhab> bundle:list |grep -i teleg
245 | Active   |  80 | 1.11.0.201707211142    | openHAB Telegram Action
openhab> log:get 245
Logger | Level
--------------
245    | DEBUG

When testing again the log did not reaveal any new information. Havent seen the log lines you mentioned above. Will try to get a tcpdump.

MrMontesa commented 7 years ago

I've created 2 tcpdumps like this: sudo tcpdump -n -i eth0 dst host 192.168.23.17 The motioneye.pcap is OH2 querying the URL with sendTelegramPhoto. The curl.pcap is a locally executed curl command downloading the image. Both pcaps contain two attempts of downloading the file. When curling the image the first attempt failed as well, and the second one downloaded the image properly. Link: tcpdumps Hope this helps.

9037568 commented 7 years ago

Thanks for the captures. Unfortunately, they're incomplete. They only show the request and not the response.

MrMontesa commented 7 years ago

My bad! I set the filter too restrict. Here's another tcpdump also containing the reply's. Again two attempts each.

9037568 commented 7 years ago

So that's fairly clear. In 3 of 4 attempts, the server is not returning an image. You get a 200 OK response with a Content-Length of 0.

I notice that for the 1 successful pull, the Content-Length and Etag headers, as well as the capture_fps_1 cookie have changed.

Failed request response has:

   HTTP/1.1 200 OK
   Content-Length: 0
   Set-Cookie: motion_detected_1=false; Path=/
   Set-Cookie: monitor_info_1=; Path=/
   Set-Cookie: capture_fps_1=0.0; Path=/
   Server: motionEye/0.35.2
   Etag: "da39a3ee5e6b4b0d3255bfef95601890afd80709"
   Date: Mon, 24 Jul 2017 06:43:17 GMT
   Content-Type: image/jpeg

While successful request response has:

    HTTP/1.1 200 OK
    Content-Length: 17098
    Set-Cookie: motion_detected_1=false; Path=/
    Set-Cookie: monitor_info_1=; Path=/
    Set-Cookie: capture_fps_1=2.1; Path=/
    Server: motionEye/0.35.2
    Etag: "e8d0870957188b658c7a8b90e13856462916d83c"
    Date: Mon, 24 Jul 2017 06:43:20 GMT
    Content-Type: image/jpeg

So this is looking like a problem on the MotionEye end. We can't process an image that wasn't served.

MrMontesa commented 7 years ago

Many thanks for your detailed analysis. I created another issue in the motioneye tracker with the info we found here. Hopefully we can get this solved soon. Again, thanks much for your time investing this issue. Will close here.