RuntimeError: The content for this response was already consumed

[M0rtalW0mbat]

• PySeq version: 0.5.0
• Python version: 3.5.2 x64
• Operating System: Windows 10 x64
• seqlog version: 0.1.0
• Seq server version: 3.2.16

Description

This simple example somethimes fire exception:

if __name__ == '__main__':
    seqlog.log_to_seq(
        server_url='http://192.168.121.21:5341',
        level=logging.INFO,
        batch_size=2,
        auto_flush_timeout=1000,
        override_root_logger=True
    )
    logging.error("Hello, {name}!", name="World")
    logging.error("Hello, {name}!", name="World1")
    logging.error("Hello, {name}!", name="World2")
    logging.error("Hello, {name}!", name="World3")

Exception

Exception in thread Queue consumer (SeqLogHandler):
Traceback (most recent call last):
  File "C:\Users\Михаил\AppData\Local\Programs\Python\Python35\lib\threading.py", line 914, in _bootstrap_inner
    self.run()
  File "C:\Users\Михаил\AppData\Local\Programs\Python\Python35\lib\threading.py", line 862, in run
    self._target(*self._args, **self._kwargs)
  File "C:\Users\Михаил\AppData\Local\Programs\Python\Python35\lib\site-packages\seqlog\consumer.py", line 109, in _queue_processor
    self._add_to_current_batch(record)
  File "C:\Users\Михаил\AppData\Local\Programs\Python\Python35\lib\site-packages\seqlog\consumer.py", line 125, in _add_to_current_batch
    self.flush()
  File "C:\Users\Михаил\AppData\Local\Programs\Python\Python35\lib\site-packages\seqlog\consumer.py", line 64, in flush
    self.callback(current_batch)
  File "C:\Users\Михаил\AppData\Local\Programs\Python\Python35\lib\site-packages\seqlog\structured_logging.py", line 286, in publish_log_batch
    response = self.session.post(self.server_url, json=request_body)
  File "C:\Users\Михаил\AppData\Local\Programs\Python\Python35\lib\site-packages\requests\sessions.py", line 522, in post
    return self.request('POST', url, data=data, json=json, **kwargs)
  File "C:\Users\Михаил\AppData\Local\Programs\Python\Python35\lib\site-packages\requests\sessions.py", line 475, in request
    resp = self.send(prep, **send_kwargs)
  File "C:\Users\Михаил\AppData\Local\Programs\Python\Python35\lib\site-packages\requests\sessions.py", line 628, in send
    r.content
  File "C:\Users\Михаил\AppData\Local\Programs\Python\Python35\lib\site-packages\requests\models.py", line 750, in content
    'The content for this response was already consumed')
RuntimeError: The content for this response was already consumed

[tintoy]

Thanks for the detailed report! I'll have a look shortly :)

[tintoy]

Ok, I think I've found the problem - if I publish a new version do you have time to try it out?

[M0rtalW0mbat]

Yep, give me a couple of days

[M0rtalW0mbat]

https://pypi.python.org/pypi/seqlog/0.3.0 It was really fast, i try check it tomorrow :) Thx!

[M0rtalW0mbat]

Now its hard to repeat, but i got it, see on screenshot in attach. As you can see i use VSCode debugger for simulate this situation(simply jump over breakpoints), maybe this is important....

[M0rtalW0mbat]

Hmm, when i run this script in cmd shell, some messages is lost, in seq srv i see only two of them.

[M0rtalW0mbat]

Somethimes only one of them:

[M0rtalW0mbat]

My test script: InstallationsProcessing.zip

[tintoy]

Ok thanks - that gives me something to work with; I'll have a look at it first thing tomorrow.

Sorry for the inconvenience:-/

On 17 Nov. 2016, at 7:18 pm, M0rtalW0mbat notifications@github.com wrote:

My test script: InstallationsProcessing.zip

— You are receiving this because you were assigned. Reply to this email directly, view it on GitHub, or mute the thread.

[tintoy]

Apparently this can also happen if server returns an empty response. I'll try your script when I get home.

[tintoy]

Ok, this is weird - I'm running your test script but I cannot reproduce the problem :-/ I've run it 15-20 times and it may pause occasionally while flushing the log but never seems to crash.

I'm on Python 3.4.4 on OSX, though, so I'll try running this on my Surface when I get home and see if that makes a difference...

Some log entries going missing, BTW, is usually because the process exits before the queue can be fully flushed. I added a sleep at the end of your script and all your log entries then show up.

I'll see if I can do something about those lost events though - losing log entries during a crash is kinda poor behaviour...

In the meanwhile, what if you just add a sleep(1) to the end of your test script. Do you still get the error?

[M0rtalW0mbat]

Ok, sleep solve message losing, but it is not related with Exception and original problem :)

[M0rtalW0mbat]

I try run script in VSCode debugger again twice and on second try i catch same situation like earlier.

[M0rtalW0mbat]

One more hint: i use VSCode debugger implemented by plugin(Python plugin by Don Jayamanne). I forgot to mention this earlier.

[tintoy]

No worries - I'm going to try this on my Windows machine when I get home tomorrow. Thanks for sticking with this, we'll work it out eventually :)

[M0rtalW0mbat]

Yep, good luck with this :) I was glad to help

[tintoy]

BTW, if you want to automatically flush log, you can do something like:

import atexit
import logging

atexit.register(logging.shutdown) # Will flush and close all log handlers when the app exits

[M0rtalW0mbat]

This salvation need some support from the inside of library :) Some check if consumer is running, maybe

D:\workspace\AnalyticsProcessing>python InstallationsProcessing.py
Seqlog version: 0.3.0
aaaaaaaaaa
bbbbbbbbbbbbbbb
Error in atexit._run_exitfuncs:
Traceback (most recent call last):
  File "C:\Users\Михаил\AppData\Local\Programs\Python\Python35\lib\logging\__init__.py", line 1882, in shutdown
    h.close()
  File "C:\Users\Михаил\AppData\Local\Programs\Python\Python35\lib\site-packages\seqlog\structured_logging.py", line 332, in close
    self.consumer.stop()
  File "C:\Users\Михаил\AppData\Local\Programs\Python\Python35\lib\site-packages\seqlog\consumer.py", line 90, in stop
    raise Exception("The consumer is not running.")
Exception: The consumer is not running.

[tintoy]

Cheers - found and fixed that bug already, just haven’t built a new package yet :)

On 17 Nov 2016, at 9:38 PM, M0rtalW0mbat notifications@github.com wrote:

D:\workspace\AnalyticsProcessing>python InstallationsProcessing.py Seqlog version: 0.3.0 aaaaaaaaaa bbbbbbbbbbbbbbb Error in atexit._run_exitfuncs: Traceback (most recent call last): File "C:\Users\Михаил\AppData\Local\Programs\Python\Python35\lib\logginginit.py", line 1882, in shutdown h.close() File "C:\Users\Михаил\AppData\Local\Programs\Python\Python35\lib\site-packages\seqlog\structured_logging.py", line 332, in close self.consumer.stop() File "C:\Users\Михаил\AppData\Local\Programs\Python\Python35\lib\site-packages\seqlog\consumer.py", line 90, in stop raise Exception("The consumer is not running.") Exception: The consumer is not running. — You are receiving this because you were assigned. Reply to this email directly, view it on GitHub https://github.com/tintoy/seqlog/issues/1#issuecomment-261213577, or mute the thread https://github.com/notifications/unsubscribe-auth/ABkezLth1dxx0bfqB5eNO_WPNwhstNx9ks5q_C65gaJpZM4KzP71.

[tintoy]

Ok this is getting weird - have tried the latest code on Windows and still can't reproduce the error:

I'll try it from VS Code, next, to see if that makes a difference. When you run it from VS Code, are you running it with the debugger attached, or just using VS Code to launch it?

[tintoy]

It works from VS Code, too:

I'm going to try publishing a new package with all the changes I made yesterday and today, let's see if that makes a difference for you.

[tintoy]

Hi - could you give v0.3.2 a try?

[M0rtalW0mbat]

When you run it from VS Code, are you running it with the debugger attached, or just using VS Code to launch it?

Yes, Im just using VS Code (just press F5). But without breakpoints its don't crash. Breakpoints is very important :)

[tintoy]

Interesting - I did set breakpoints but only in the seqlog code. Where did you set yours again? Sorry on mobile so images not coming through...

On 18 Nov. 2016, at 2:52 pm, M0rtalW0mbat notifications@github.com wrote:

When you run it from VS Code, are you running it with the debugger attached, or just using VS Code to launch it? Yes, Im just using VS Code, but without breakpoints its don't crash. Breakpoints is very important :)

— You are receiving this because you were assigned. Reply to this email directly, view it on GitHub, or mute the thread.

[M0rtalW0mbat]

first: seqlog.set_global_log_properties(Application='13') second: print('aaaaaaaaaa') third: print('bbbbbbbbbbbbbbb')

[M0rtalW0mbat]

Script crush after third breakpoint in most cases

[tintoy]

Ok! I've managed to reproduce the problem (seems to only happen on VS Code in Windows) - I'll have a poke-around and see what I can find.

[M0rtalW0mbat]

seems to only happen on VS Code in Windows

Im lucky :)

[tintoy]

Ok, @M0rtalW0mbat - I think I've actually fixed it this time! Tested this in VS Code on Windows, and have stepped through the entire script more than 10 times - the error doesn't seem to happen anymore.

Could you give v0.3.3 a try and let me know if that fixes it for you?

[M0rtalW0mbat]

Looks good, i can't reproduce crash on version 0.3.3. I think we can close this issue. Great job! :)

[tintoy]

Glad to hear it :)